DHCP issues when rebuilding machines

Support
1

Problem:
When going to rebuild a machine, this pops up -

Failed to enable demo1.riff.cc for installation: [“Create DHCP Settings for demo1.riff.cc task failed with the following error: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp”, “Failed to perform rollback on Remove DHCP Settings for demo1.riff.cc - ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp”]

I can manually remove the DHCP reservation for that machine and then restart ISC DHCPD and then it works…

Expected outcome:
Shouldn’t give an error…

Foreman and Proxy versions:
1.20.2

Foreman and Proxy plugin versions:
Unsure

Other relevant data:
[e.g. logs from Foreman and/or the Proxy, modified templates, commands issued, etc]
(for logs, surround with three back-ticks to get proper formatting, e.g.)

logs
2

I can kinda get around it by editing the DHCP leases file and removing the entry, bouncing isc-dhcp and trying again…

3

Debugging log of production.log, paste the relevant part only please.

4 
2019-06-17T01:08:02 [I|app|] Started GET "/hosts/demo3.riff.cc/review_before_build" for 10.0.2.2 at 2019-06-17 01:08:02 +0000
2019-06-17T01:08:02 [I|app|4a74a] Processing by HostsController#review_before_build as */*
2019-06-17T01:08:02 [I|app|4a74a]   Parameters: {"id"=>"demo3.riff.cc"}
2019-06-17T01:08:02 [I|app|4a74a] Current user set to admin (admin)
2019-06-17T01:08:02 [I|app|4a74a] Rendering AutoYaST default PXELinux
2019-06-17T01:08:02 [I|blo|4a74a] Unattended render of 'AutoYaST default PXELinux' = 'c002bc2860f7dca6c8b5890903a74d2b438ed74384c47567256b357190b41222'
2019-06-17T01:08:02 [I|app|4a74a]   Rendering hosts/review_before_build.html.erb
2019-06-17T01:08:02 [I|app|4a74a]   Rendered hosts/review_before_build.html.erb (2.0ms)
2019-06-17T01:08:02 [I|app|4a74a] Completed 200 OK in 506ms (Views: 2.4ms | ActiveRecord: 34.0ms)
2019-06-17T01:08:04 [I|app|] Started PUT "/hosts/demo3.riff.cc/setBuild?auth_object=demo3.riff.cc&permission=build_hosts" for 10.0.2.2 at 2019-06-17 01:08:04 +0000
2019-06-17T01:08:04 [I|app|4aca9] Processing by HostsController#setBuild as HTML
2019-06-17T01:08:04 [I|app|4aca9]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"REDACTED==", "commit"=>"Build", "auth_object"=>"demo3.riff.cc", "permission"=>"build_hosts", "id"=>"demo3.riff.cc"}
2019-06-17T01:08:04 [I|app|4aca9] Current user set to admin (admin)
2019-06-17T01:08:04 [I|app|4aca9] Fetching DHCP reservation demo3.riff.cc for demo3.riff.cc-08:00:27:44:a3:bf/10.21.30.158
2019-06-17T01:08:04 [I|app|4aca9] Delete DHCP reservation demo3.riff.cc for demo3.riff.cc-08:00:27:44:a3:bf/10.21.30.158
2019-06-17T01:08:04 [I|app|4aca9] Create DHCP reservation demo3.riff.cc for demo3.riff.cc-08:00:27:44:a3:bf/10.21.30.158
2019-06-17T01:08:04 [W|app|4aca9] Create DHCP Settings for demo3.riff.cc task failed with the following error: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp
ProxyAPI::ProxyException: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp
/usr/share/foreman/lib/proxy_api/dhcp.rb:89:in `rescue in set'
/usr/share/foreman/lib/proxy_api/dhcp.rb:84:in `set'
/usr/share/foreman/lib/net/dhcp/record.rb:43:in `create'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `block in set_dhcp'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `each'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `all?'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `set_dhcp'
/usr/share/foreman/app/models/concerns/orchestration.rb:222:in `execute'
/usr/share/foreman/app/models/concerns/orchestration.rb:145:in `block in process'
/usr/share/foreman/app/models/concerns/orchestration.rb:137:in `each'
/usr/share/foreman/app/models/concerns/orchestration.rb:137:in `process'
/usr/share/foreman/app/models/concerns/orchestration.rb:44:in `around_save_orchestration'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/callbacks.rb:342:in `create_or_update'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/persistence.rb:275:in `save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/validations.rb:46:in `save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:310:in `block (2 levels) in save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:254:in `block in transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
/usr/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:254:in `transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:212:in `transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:310:in `block in save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:325:in `rollback_active_record_state!'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:309:in `save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/suppressor.rb:44:in `save'
/usr/share/foreman/app/models/concerns/foreman/sti.rb:26:in `save'
/usr/share/foreman/app/models/host/managed.rb:423:in `setBuild'
/usr/share/foreman/app/controllers/hosts_controller.rb:232:in `setBuild'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/base.rb:194:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/rendering.rb:30:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/application_shared.rb:15:in `set_timezone'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118: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-5.2.1/lib/active_support/callbacks.rb:118: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-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/audited-4.8.0/lib/audited/sweeper.rb:14:in `around'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/audited-4.8.0/lib/audited/sweeper.rb:14:in `around'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:41:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/rescue.rb:22:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/notifications.rb:168:in `block in instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/notifications.rb:168:in `instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/base.rb:134:in `process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionview-5.2.1/lib/action_view/rendering.rb:32:in `process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal.rb:191:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal.rb:252:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:34:in `serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:52:in `block in serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:35:in `each'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:35:in `serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:840:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.15/lib/apipie/static_dispatcher.rb:66:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.15/lib/apipie/extractor/recorder.rb:137:in `call'
/usr/share/foreman/lib/middleware/telemetry.rb:9:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.15/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
/usr/share/foreman/lib/middleware/catch_json_parse_errors.rb:8:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/tempfile_reaper.rb:15:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/etag.rb:25:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/conditional_get.rb:38:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/head.rb:12:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/usr/share/foreman/lib/middleware/logging_context.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:232:in `context'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:226:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:98:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/rack/logger.rb:38:in `call_app'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/rack/logger.rb:28:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/method_override.rb:22:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/runtime.rb:22:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/sendfile.rb:111:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/secure_headers-6.0.0/lib/secure_headers/middleware.rb:13:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/engine.rb:524:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `public_send'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `method_missing'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/urlmap.rb:68:in `block in call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/urlmap.rb:53:in `each'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/urlmap.rb:53:in `call'
/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:97:in `process_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:160:in `accept_and_process_next_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:113: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.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2019-06-17T01:08:04 [W|app|4aca9] Rolling back due to a problem: [#<Orchestration::Task:0x0000559b2a40f130 @name="Create DHCP Settings for demo3.riff.cc", @id="dhcp_create_08:00:27:44:a3:bf", @status="failed", @priority=9, @action=[#<Nic::Managed id: 9, mac: "08:00:27:44:a3:bf", ip: "10.21.30.158", type: "Nic::Managed", name: "demo3.riff.cc", host_id: 7, subnet_id: 1, domain_id: 1, attrs: {}, created_at: "2019-06-14 01:37:08", updated_at: "2019-06-14 01:37:08", 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: {}, ip6: "", subnet6_id: nil>, :set_dhcp], @created=1560733684.549077, @timestamp=2019-06-17 01:08:04 UTC>]
2019-06-17T01:08:04 [I|app|4aca9] Create DHCP reservation demo3.riff.cc for demo3.riff.cc-08:00:27:44:a3:bf/10.21.30.158
2019-06-17T01:08:04 [W|app|4aca9] Failed to perform rollback on Remove DHCP Settings for demo3.riff.cc - ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp
ProxyAPI::ProxyException: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp
/usr/share/foreman/lib/proxy_api/dhcp.rb:89:in `rescue in set'
/usr/share/foreman/lib/proxy_api/dhcp.rb:84:in `set'
/usr/share/foreman/lib/net/dhcp/record.rb:43:in `create'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `block in set_dhcp'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `each'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `all?'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `set_dhcp'
/usr/share/foreman/app/models/concerns/orchestration.rb:222:in `execute'
/usr/share/foreman/app/models/concerns/orchestration.rb:192:in `block in fail_queue'
/usr/share/foreman/app/models/concerns/orchestration.rb:188:in `reverse_each'
/usr/share/foreman/app/models/concerns/orchestration.rb:188:in `fail_queue'
/usr/share/foreman/app/models/concerns/orchestration.rb:162:in `process'
/usr/share/foreman/app/models/concerns/orchestration.rb:44:in `around_save_orchestration'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/callbacks.rb:342:in `create_or_update'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/persistence.rb:275:in `save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/validations.rb:46:in `save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:310:in `block (2 levels) in save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:254:in `block in transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
/usr/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:254:in `transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:212:in `transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:310:in `block in save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:325:in `rollback_active_record_state!'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:309:in `save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/suppressor.rb:44:in `save'
/usr/share/foreman/app/models/concerns/foreman/sti.rb:26:in `save'
/usr/share/foreman/app/models/host/managed.rb:423:in `setBuild'
/usr/share/foreman/app/controllers/hosts_controller.rb:232:in `setBuild'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/base.rb:194:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/rendering.rb:30:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/application_shared.rb:15:in `set_timezone'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118: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-5.2.1/lib/active_support/callbacks.rb:118: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-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/audited-4.8.0/lib/audited/sweeper.rb:14:in `around'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/audited-4.8.0/lib/audited/sweeper.rb:14:in `around'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:41:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/rescue.rb:22:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/notifications.rb:168:in `block in instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/notifications.rb:168:in `instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/base.rb:134:in `process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionview-5.2.1/lib/action_view/rendering.rb:32:in `process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal.rb:191:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal.rb:252:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:34:in `serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:52:in `block in serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:35:in `each'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:35:in `serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:840:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.15/lib/apipie/static_dispatcher.rb:66:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.15/lib/apipie/extractor/recorder.rb:137:in `call'
/usr/share/foreman/lib/middleware/telemetry.rb:9:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.15/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
/usr/share/foreman/lib/middleware/catch_json_parse_errors.rb:8:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/tempfile_reaper.rb:15:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/etag.rb:25:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/conditional_get.rb:38:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/head.rb:12:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/usr/share/foreman/lib/middleware/logging_context.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:232:in `context'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:226:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:98:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/rack/logger.rb:38:in `call_app'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/rack/logger.rb:28:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/method_override.rb:22:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/runtime.rb:22:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/sendfile.rb:111:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/secure_headers-6.0.0/lib/secure_headers/middleware.rb:13:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/engine.rb:524:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `public_send'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `method_missing'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/urlmap.rb:68:in `block in call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/urlmap.rb:53:in `each'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/urlmap.rb:53:in `call'
/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:97:in `process_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:160:in `accept_and_process_next_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:113: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.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2019-06-17T01:08:04 [I|app|4aca9] Processed 1 tasks from queue 'Host::Managed Main', completed 0/7
2019-06-17T01:08:04 [E|app|4aca9] Task 'Remove DHCP Settings for demo3.riff.cc' *rollbacked*
2019-06-17T01:08:04 [E|app|4aca9] Task 'Create DHCP Settings for demo3.riff.cc' *failed*
2019-06-17T01:08:04 [E|app|4aca9] Task 'Deploy TFTP PXELinux config for demo3.riff.cc' *canceled*
2019-06-17T01:08:04 [E|app|4aca9] Task 'Deploy TFTP PXEGrub2 config for demo3.riff.cc' *canceled*
2019-06-17T01:08:04 [E|app|4aca9] Task 'Deploy TFTP PXEGrub config for demo3.riff.cc' *canceled*
2019-06-17T01:08:04 [E|app|4aca9] Task 'Deploy TFTP iPXE config for demo3.riff.cc' *canceled*
2019-06-17T01:08:04 [E|app|4aca9] Task 'Fetch TFTP boot files for demo3.riff.cc' *canceled*
2019-06-17T01:08:04 [W|app|4aca9] Set build failed: #<ActiveModel::Errors:0x0000559b2a5ffb48 @base=#<Host::Managed id: 7, name: "demo3.riff.cc", last_compile: nil, last_report: nil, updated_at: "2019-06-14 01:46:50", created_at: "2019-06-14 01:37:08", root_pass: "REDACTED...", architecture_id: 1, operatingsystem_id: 5, environment_id: 1, ptable_id: 93, medium_id: 12, build: true, comment: "", disk: "", installed_at: "2019-06-14 01:46:49", model_id: nil, hostgroup_id: nil, owner_id: 4, owner_type: "User", enabled: true, puppet_ca_proxy_id: 1, managed: true, use_image: nil, image_file: nil, uuid: nil, compute_resource_id: nil, puppet_proxy_id: 1, certname: nil, image_id: nil, organization_id: nil, location_id: nil, type: "Host::Managed", otp: nil, realm_id: nil, compute_profile_id: nil, provision_method: "build", grub_pass: "REDACTED...", global_status: 0, lookup_value_matcher: "fqdn=demo3.riff.cc", pxe_loader: "PXELinux BIOS", initiated_at: "2019-06-17 01:08:04", build_errors: nil>, @messages={:base=>["Create DHCP Settings for demo3.riff.cc task failed with the following error: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp", "Failed to perform rollback on Remove DHCP Settings for demo3.riff.cc - ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp"]}, @details={:base=>[{:error=>"Create DHCP Settings for demo3.riff.cc task failed with the following error: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp"}, {:error=>"Failed to perform rollback on Remove DHCP Settings for demo3.riff.cc - ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp"}]}>
2019-06-17T01:08:04 [E|app|4aca9] Failed to save: Create DHCP Settings for demo3.riff.cc task failed with the following error: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp, Failed to perform rollback on Remove DHCP Settings for demo3.riff.cc - ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp
2019-06-17T01:08:04 [I|app|4aca9] Redirected to https://localhost:8443/hosts/demo3.riff.cc
2019-06-17T01:08:04 [I|app|4aca9] Completed 302 Found in 686ms (ActiveRecord: 13.4ms)
2019-06-17T01:08:04 [I|app|] Started GET "/hosts/demo3.riff.cc" for 10.0.2.2 at 2019-06-17 01:08:04 +0000
2019-06-17T01:08:04 [I|app|a9231] Processing by HostsController#show as HTML
2019-06-17T01:08:04 [I|app|a9231]   Parameters: {"id"=>"demo3.riff.cc"}
2019-06-17T01:08:04 [I|app|a9231] Current user set to admin (admin)
2019-06-17T01:08:04 [I|app|a9231]   Rendering hosts/show.html.erb within layouts/application
2019-06-17T01:08:04 [I|app|a9231]   Rendered hosts/show.html.erb within layouts/application (14.1ms)
2019-06-17T01:08:04 [I|app|a9231]   Rendered layouts/_application_content.html.erb (0.3ms)
2019-06-17T01:08:04 [I|app|a9231]   Rendering layouts/base.html.erb
2019-06-17T01:08:04 [I|app|a9231]   Rendered layouts/base.html.erb (10.2ms)
2019-06-17T01:08:04 [I|app|a9231] Completed 200 OK in 37ms (Views: 25.3ms | ActiveRecord: 4.0ms)
2019-06-17T01:08:05 [I|app|] Started GET "/notification_recipients" for 10.0.2.2 at 2019-06-17 01:08:05 +0000
2019-06-17T01:08:05 [I|app|c6c47] Processing by NotificationRecipientsController#index as JSON
2019-06-17T01:08:05 [I|app|c6c47] Current user set to admin (admin)
2019-06-17T01:08:05 [I|app|c6c47] Completed 200 OK in 4ms (Views: 0.1ms | ActiveRecord: 0.6ms)
2019-06-17T01:08:05 [I|app|] Started GET "/hosts/demo3.riff.cc/nics" for 10.0.2.2 at 2019-06-17 01:08:05 +0000
2019-06-17T01:08:05 [I|app|] Started GET "/hosts/demo3.riff.cc/templates" for 10.0.2.2 at 2019-06-17 01:08:05 +0000
2019-06-17T01:08:05 [I|app|] Started GET "/hosts/demo3.riff.cc/runtime?range=7" for 10.0.2.2 at 2019-06-17 01:08:05 +0000
2019-06-17T01:08:05 [I|app|] Started GET "/hosts/demo3.riff.cc/resources?range=7" for 10.0.2.2 at 2019-06-17 01:08:05 +0000
2019-06-17T01:08:05 [I|app|44d20] Processing by HostsController#nics as HTML
2019-06-17T01:08:05 [I|app|8f054] Processing by HostsController#runtime as HTML
2019-06-17T01:08:05 [I|app|] Started GET "/hosts/demo3.riff.cc/overview" for 10.0.2.2 at 2019-06-17 01:08:05 +0000
2019-06-17T01:08:05 [I|app|69e70] Processing by HostsController#resources as HTML
2019-06-17T01:08:05 [I|app|24561] Processing by HostsController#overview as HTML
2019-06-17T01:08:05 [I|app|44d20]   Parameters: {"id"=>"demo3.riff.cc"}
2019-06-17T01:08:05 [I|app|8f054]   Parameters: {"range"=>"7", "id"=>"demo3.riff.cc"}
2019-06-17T01:08:05 [I|app|69e70]   Parameters: {"range"=>"7", "id"=>"demo3.riff.cc"}
2019-06-17T01:08:05 [I|app|c475d] Processing by HostsController#templates as HTML
2019-06-17T01:08:05 [I|app|c475d]   Parameters: {"id"=>"demo3.riff.cc"}
2019-06-17T01:08:05 [I|app|8f054] Current user set to admin (admin)
2019-06-17T01:08:05 [I|app|24561]   Parameters: {"id"=>"demo3.riff.cc"}
2019-06-17T01:08:05 [I|app|44d20] Current user set to admin (admin)
2019-06-17T01:08:05 [I|app|c475d] Current user set to admin (admin)
2019-06-17T01:08:05 [I|app|69e70] Current user set to admin (admin)
2019-06-17T01:08:05 [I|app|24561] Current user set to admin (admin)
2019-06-17T01:08:05 [I|app|69e70]   Rendered hosts/_resources.html.erb (13.3ms)
2019-06-17T01:08:05 [I|app|8f054]   Rendered hosts/_runtime.html.erb (10.2ms)
2019-06-17T01:08:05 [I|app|69e70] Completed 200 OK in 50ms (Views: 4.3ms | ActiveRecord: 27.7ms)
2019-06-17T01:08:05 [I|app|8f054] Completed 200 OK in 54ms (Views: 5.7ms | ActiveRecord: 37.2ms)
2019-06-17T01:08:05 [I|app|44d20]   Rendered hosts/_nics.html.erb (35.3ms)
2019-06-17T01:08:05 [I|app|44d20] Completed 200 OK in 75ms (Views: 11.5ms | ActiveRecord: 49.6ms)
2019-06-17T01:08:05 [I|app|24561]   Rendered hosts/_overview.html.erb (45.3ms)
2019-06-17T01:08:05 [I|app|24561] Completed 200 OK in 98ms (Views: 26.1ms | ActiveRecord: 42.8ms)
2019-06-17T01:08:05 [I|app|c475d]   Rendered hosts/_templates.html.erb (8.6ms)
2019-06-17T01:08:05 [I|app|c475d] Completed 200 OK in 153ms (Views: 8.0ms | ActiveRecord: 79.9ms)
2019-06-17T01:08:15 [I|app|] Started GET "/notification_recipients" for 10.0.2.2 at 2019-06-17 01:08:15 +0000
2019-06-17T01:08:15 [I|app|25223] Processing by NotificationRecipientsController#index as JSON
2019-06-17T01:08:15 [I|app|25223] Current user set to admin (admin)
2019-06-17T01:08:15 [I|app|25223] Completed 200 OK in 4ms (Views: 0.1ms | ActiveRecord: 0.5ms)
2019-06-17T01:08:25 [I|app|] Started GET "/notification_recipients" for 10.0.2.2 at 2019-06-17 01:08:25 +0000
2019-06-17T01:08:25 [I|app|7c7bc] Processing by NotificationRecipientsController#index as JSON
2019-06-17T01:08:25 [I|app|7c7bc] Current user set to admin (admin)
2019-06-17T01:08:25 [I|app|7c7bc] Completed 200 OK in 5ms (Views: 0.1ms | ActiveRecord: 0.8ms)

I tried to strip out what looked unnecessary, but have kept a copy of the complete log output if needed.

5

Sorry, just noticed you specified debug log, not regular log.

Here -

2019-06-17T01:23:33 [I|app|] Started GET "/hosts/demo4.riff.cc/review_before_build" for 10.0.2.2 at 2019-06-17 01:23:33 +0000
2019-06-17T01:23:33 [I|app|86b31] Processing by HostsController#review_before_build as */*
2019-06-17T01:23:33 [I|app|86b31]   Parameters: {"id"=>"demo4.riff.cc"}
2019-06-17T01:23:33 [I|app|86b31] Current user set to admin (admin)
2019-06-17T01:23:34 [I|app|86b31] Rendering Preseed default PXELinux
2019-06-17T01:23:34 [I|blo|86b31] Unattended render of 'Preseed default PXELinux' = 'fd6a1084c9840d7f9f9ea17cbc88e6ce52dd667980051cf172a17ddb65cb2205'

2019-06-17T01:23:34 [I|app|86b31]   Rendering hosts/review_before_build.html.erb
2019-06-17T01:23:34 [I|app|86b31]   Rendered hosts/review_before_build.html.erb (4.0ms)
2019-06-17T01:23:34 [I|app|86b31] Completed 200 OK in 900ms (Views: 9.2ms | ActiveRecord: 67.5ms)
2019-06-17T01:23:36 [I|app|] Started PUT "/hosts/demo4.riff.cc/setBuild?auth_object=demo4.riff.cc&permission=build_hosts" for 10.0.2.2 at 2019-06-17 01:23:36 +0000
2019-06-17T01:23:36 [I|app|6524c] Processing by HostsController#setBuild as HTML
2019-06-17T01:23:36 [I|app|6524c]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"WjwtL0TXR/PBv6iff38GR8RvzCCHWXnYSAs4pOwxHauYNLzEDk8CNjo5pkaI+p2o6qJLUtV6/zJyBYh7Kec6qA==", "commit"=>"Build", "auth_object"=>"demo4.riff.cc", "permission"=>"build_hosts", "id"=>"demo4.riff.cc"}
2019-06-17T01:23:36 [I|app|6524c] Current user set to admin (admin)
2019-06-17T01:23:36 [D|app|6524c] Enqueued task 'Disable PuppetCA autosigning for demo4.riff.cc' to 'Host::Managed Post' queue
2019-06-17T01:23:36 [D|app|6524c] Enqueued task 'Cleanup PuppetCA certificates for demo4.riff.cc' to 'Host::Managed Post' queue
2019-06-17T01:23:36 [D|app|6524c] Enqueued task 'Enable PuppetCA autosigning for demo4.riff.cc' to 'Host::Managed Post' queue
2019-06-17T01:23:36 [I|app|] Started GET "/notification_recipients" for 10.0.2.2 at 2019-06-17 01:23:36 +0000
2019-06-17T01:23:36 [I|app|44e32] Processing by NotificationRecipientsController#index as JSON
2019-06-17T01:23:36 [I|app|44e32] Current user set to admin (admin)
2019-06-17T01:23:36 [I|app|6524c] Fetching DHCP reservation demo4.riff.cc for demo4.riff.cc-08:00:27:83:11:8f/10.21.30.48
2019-06-17T01:23:36 [D|not|44e32] Cache Hit: notification, reading cache for notification-4
2019-06-17T01:23:36 [D|app|44e32] Body: {"notifications":[{"id":34,"seen":false,"level":"info","text":"Merge time vs Change complexity in Foreman Core","created_at":"2019-06-16T06:45:44.691Z","group":"Community","actions":{"links":[{"href":"http://theforeman.org/2019/03/merge-time-review-complexity.html","title":"Open","external":true}]}},{"id":30,"seen":false,"level":"info","text":"Foreman Proxy Registration Protocol v2 explained","created_at":"2019-06-16T06:45:44.680Z","group":"Community","actions":{"links":[{"href":"http://theforeman.org/2019/04/smart-proxy-capabilities-explained.html","title":"Open","external":true}]}},{"id":26,"seen":false,"level":"info","text":"2019 Foreman Survey Analysis","created_at":"2019-06-16T06:45:44.658Z","group":"Community","actions":{"links":[{"href":"http://theforeman.org/2019/05/2019-foreman-survey-analysis.html","title":"Open","external":true}]}}]}
2019-06-17T01:23:36 [I|app|44e32] Completed 200 OK in 8ms (Views: 0.2ms | ActiveRecord: 0.4ms)
2019-06-17T01:23:36 [D|app|6524c] Detected a changed required for DHCP record
2019-06-17T01:23:36 [D|app|6524c] Enqueued task 'dhcp_remove_08:00:27:83:11:8f' to 'Host::Managed Main' queue
2019-06-17T01:23:36 [D|app|6524c] Enqueued task 'dhcp_create_08:00:27:83:11:8f' to 'Host::Managed Main' queue
2019-06-17T01:23:36 [D|app|6524c] Current organization set to none
2019-06-17T01:23:36 [D|app|6524c] Current location set to none
2019-06-17T01:23:36 [D|app|6524c] Current location set to none
2019-06-17T01:23:36 [D|app|6524c] Current organization set to none
2019-06-17T01:23:36 [D|app|6524c] Enqueued task 'Deploy TFTP PXELinux config for demo4.riff.cc' to 'Host::Managed Main' queue
2019-06-17T01:23:36 [D|app|6524c] Enqueued task 'Deploy TFTP PXEGrub2 config for demo4.riff.cc' to 'Host::Managed Main' queue
2019-06-17T01:23:36 [D|app|6524c] Enqueued task 'Deploy TFTP PXEGrub config for demo4.riff.cc' to 'Host::Managed Main' queue
2019-06-17T01:23:36 [D|app|6524c] Enqueued task 'Deploy TFTP iPXE config for demo4.riff.cc' to 'Host::Managed Main' queue
2019-06-17T01:23:36 [D|app|6524c] Enqueued task 'Fetch TFTP boot files for demo4.riff.cc' to 'Host::Managed Main' queue
2019-06-17T01:23:36 [D|app|6524c] Processing task 'Remove DHCP Settings for demo4.riff.cc' from 'Host::Managed Main'
2019-06-17T01:23:36 [I|app|6524c] Delete DHCP reservation demo4.riff.cc for demo4.riff.cc-08:00:27:83:11:8f/10.21.30.48
2019-06-17T01:23:36 [D|app|6524c] Processing task 'Create DHCP Settings for demo4.riff.cc' from 'Host::Managed Main'
2019-06-17T01:23:36 [I|app|6524c] Create DHCP reservation demo4.riff.cc for demo4.riff.cc-08:00:27:83:11:8f/10.21.30.48
2019-06-17T01:23:36 [D|app|6524c] DHCP reservation on net 10.21.30.3 with attrs: {:hostname=>"demo4.riff.cc", :mac=>"08:00:27:83:11:8f", :ip=>"10.21.30.48", :network=>"10.21.30.3", :nextServer=>"10.21.30.3", :filename=>"pxelinux.0", :name=>"demo4.riff.cc", :related_macs=>[]}
2019-06-17T01:23:36 [W|app|6524c] Create DHCP Settings for demo4.riff.cc task failed with the following error: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp
ProxyAPI::ProxyException: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp
/usr/share/foreman/lib/proxy_api/dhcp.rb:89:in `rescue in set'
/usr/share/foreman/lib/proxy_api/dhcp.rb:84:in `set'
/usr/share/foreman/lib/net/dhcp/record.rb:43:in `create'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `block in set_dhcp'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `each'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `all?'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `set_dhcp'
/usr/share/foreman/app/models/concerns/orchestration.rb:222:in `execute'
/usr/share/foreman/app/models/concerns/orchestration.rb:145:in `block in process'
/usr/share/foreman/app/models/concerns/orchestration.rb:137:in `each'
/usr/share/foreman/app/models/concerns/orchestration.rb:137:in `process'
/usr/share/foreman/app/models/concerns/orchestration.rb:44:in `around_save_orchestration'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/callbacks.rb:342:in `create_or_update'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/persistence.rb:275:in `save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/validations.rb:46:in `save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:310:in `block (2 levels) in save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:254:in `block in transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
/usr/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:254:in `transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:212:in `transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:310:in `block in save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:325:in `rollback_active_record_state!'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:309:in `save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/suppressor.rb:44:in `save'
/usr/share/foreman/app/models/concerns/foreman/sti.rb:26:in `save'
/usr/share/foreman/app/models/host/managed.rb:423:in `setBuild'
/usr/share/foreman/app/controllers/hosts_controller.rb:232:in `setBuild'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/base.rb:194:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/rendering.rb:30:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/application_shared.rb:15:in `set_timezone'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118: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-5.2.1/lib/active_support/callbacks.rb:118: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-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/audited-4.8.0/lib/audited/sweeper.rb:14:in `around'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/audited-4.8.0/lib/audited/sweeper.rb:14:in `around'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:41:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/rescue.rb:22:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/notifications.rb:168:in `block in instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/notifications.rb:168:in `instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/base.rb:134:in `process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionview-5.2.1/lib/action_view/rendering.rb:32:in `process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal.rb:191:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal.rb:252:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:34:in `serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:52:in `block in serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:35:in `each'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:35:in `serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:840:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.15/lib/apipie/static_dispatcher.rb:66:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.15/lib/apipie/extractor/recorder.rb:137:in `call'
/usr/share/foreman/lib/middleware/telemetry.rb:9:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.15/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
/usr/share/foreman/lib/middleware/catch_json_parse_errors.rb:8:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/tempfile_reaper.rb:15:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/etag.rb:25:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/conditional_get.rb:38:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/head.rb:12:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/usr/share/foreman/lib/middleware/logging_context.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:232:in `context'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:226:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:98:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/rack/logger.rb:38:in `call_app'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/rack/logger.rb:28:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/method_override.rb:22:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/runtime.rb:22:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/sendfile.rb:111:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/secure_headers-6.0.0/lib/secure_headers/middleware.rb:13:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/engine.rb:524:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `public_send'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `method_missing'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/urlmap.rb:68:in `block in call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/urlmap.rb:53:in `each'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/urlmap.rb:53:in `call'
/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:97:in `process_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:160:in `accept_and_process_next_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:113: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.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2019-06-17T01:23:36 [W|app|6524c] Rolling back due to a problem: [#<Orchestration::Task:0x0000563f64001a78 @name="Create DHCP Settings for demo4.riff.cc", @id="dhcp_create_08:00:27:83:11:8f", @status="failed", @priority=9, @action=[#<Nic::Managed id: 5, mac: "08:00:27:83:11:8f", ip: "10.21.30.48", type: "Nic::Managed", name: "demo4.riff.cc", host_id: 4, subnet_id: 1, domain_id: 1, attrs: {"bindings"=>[{"address"=>"10.21.30.48", "netmask"=>"255.255.254.0", "network"=>"10.21.30.0"}], "bindings6"=>[{"address"=>"fe80::a00:27ff:fe83:118f", "netmask"=>"ffff:ffff:ffff:ffff::", "network"=>"fe80::"}], "mtu"=>1500, "netmask"=>"255.255.254.0", "netmask6"=>"ffff:ffff:ffff:ffff::", "network"=>"10.21.30.0", "network6"=>"fe80::"}, created_at: "2019-06-13 08:06:34", updated_at: "2019-06-13 08:13:54", provider: nil, username: nil, password: nil, virtual: false, link: true, identifier: "enp0s3", tag: "", attached_to: "", managed: true, mode: "balance-rr", attached_devices: "", bond_options: "", primary: true, provision: true, compute_attributes: {}, ip6: nil, subnet6_id: nil>, :set_dhcp], @created=1560734616.4530327, @timestamp=2019-06-17 01:23:36 UTC>]
2019-06-17T01:23:36 [I|app|6524c] Create DHCP reservation demo4.riff.cc for demo4.riff.cc-08:00:27:83:11:8f/10.21.30.48
2019-06-17T01:23:36 [D|app|6524c] DHCP reservation on net 10.21.30.3 with attrs: {:hostname=>"demo4.riff.cc", :mac=>"08:00:27:83:11:8f", :ip=>"10.21.30.48", :network=>"10.21.30.3", :nextServer=>"10.21.30.3", :filename=>"pxelinux.0", :name=>"demo4.riff.cc", :related_macs=>[]}
2019-06-17T01:23:36 [W|app|6524c] Failed to perform rollback on Remove DHCP Settings for demo4.riff.cc - ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp
ProxyAPI::ProxyException: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp
/usr/share/foreman/lib/proxy_api/dhcp.rb:89:in `rescue in set'
/usr/share/foreman/lib/proxy_api/dhcp.rb:84:in `set'
/usr/share/foreman/lib/net/dhcp/record.rb:43:in `create'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `block in set_dhcp'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `each'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `all?'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:57:in `set_dhcp'
/usr/share/foreman/app/models/concerns/orchestration.rb:222:in `execute'
/usr/share/foreman/app/models/concerns/orchestration.rb:192:in `block in fail_queue'
/usr/share/foreman/app/models/concerns/orchestration.rb:188:in `reverse_each'
/usr/share/foreman/app/models/concerns/orchestration.rb:188:in `fail_queue'
/usr/share/foreman/app/models/concerns/orchestration.rb:162:in `process'
/usr/share/foreman/app/models/concerns/orchestration.rb:44:in `around_save_orchestration'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/callbacks.rb:342:in `create_or_update'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/persistence.rb:275:in `save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/validations.rb:46:in `save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:310:in `block (2 levels) in save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:254:in `block in transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
/usr/lib/ruby/2.5.0/monitor.rb:226:in `mon_synchronize'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:254:in `transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:212:in `transaction'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:310:in `block in save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:325:in `rollback_active_record_state!'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/transactions.rb:309:in `save'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/suppressor.rb:44:in `save'
/usr/share/foreman/app/models/concerns/foreman/sti.rb:26:in `save'
/usr/share/foreman/app/models/host/managed.rb:423:in `setBuild'
/usr/share/foreman/app/controllers/hosts_controller.rb:232:in `setBuild'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/base.rb:194:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/rendering.rb:30:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/application_shared.rb:15:in `set_timezone'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118: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-5.2.1/lib/active_support/callbacks.rb:118: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-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/audited-4.8.0/lib/audited/sweeper.rb:14:in `around'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/audited-4.8.0/lib/audited/sweeper.rb:14:in `around'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:41:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/rescue.rb:22:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/notifications.rb:168:in `block in instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/notifications.rb:168:in `instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-5.2.1/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/abstract_controller/base.rb:134:in `process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionview-5.2.1/lib/action_view/rendering.rb:32:in `process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal.rb:191:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_controller/metal.rb:252:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:34:in `serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:52:in `block in serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:35:in `each'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:35:in `serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:840:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.15/lib/apipie/static_dispatcher.rb:66:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.15/lib/apipie/extractor/recorder.rb:137:in `call'
/usr/share/foreman/lib/middleware/telemetry.rb:9:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.15/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
/usr/share/foreman/lib/middleware/catch_json_parse_errors.rb:8:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/tempfile_reaper.rb:15:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/etag.rb:25:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/conditional_get.rb:38:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/head.rb:12:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/usr/share/foreman/lib/middleware/logging_context.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:232:in `context'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/session/abstract/id.rb:226:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:98:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/rack/logger.rb:38:in `call_app'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/rack/logger.rb:28:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/method_override.rb:22:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/runtime.rb:22:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-5.2.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/sendfile.rb:111:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/secure_headers-6.0.0/lib/secure_headers/middleware.rb:13:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/engine.rb:524:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `public_send'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `method_missing'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/urlmap.rb:68:in `block in call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/urlmap.rb:53:in `each'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.0.6/lib/rack/urlmap.rb:53:in `call'
/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:97:in `process_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:160:in `accept_and_process_next_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:113: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.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2019-06-17T01:23:36 [I|app|6524c] Processed 1 tasks from queue 'Host::Managed Main', completed 0/7
2019-06-17T01:23:36 [E|app|6524c] Task 'Remove DHCP Settings for demo4.riff.cc' *rollbacked*
2019-06-17T01:23:36 [E|app|6524c] Task 'Create DHCP Settings for demo4.riff.cc' *failed*
2019-06-17T01:23:36 [E|app|6524c] Task 'Deploy TFTP PXELinux config for demo4.riff.cc' *canceled*
2019-06-17T01:23:36 [E|app|6524c] Task 'Deploy TFTP PXEGrub2 config for demo4.riff.cc' *canceled*
2019-06-17T01:23:36 [E|app|6524c] Task 'Deploy TFTP PXEGrub config for demo4.riff.cc' *canceled*
2019-06-17T01:23:36 [E|app|6524c] Task 'Deploy TFTP iPXE config for demo4.riff.cc' *canceled*
2019-06-17T01:23:36 [E|app|6524c] Task 'Fetch TFTP boot files for demo4.riff.cc' *canceled*
2019-06-17T01:23:36 [W|app|6524c] Set build failed: #<ActiveModel::Errors:0x0000563f64620030 @base=#<Host::Managed id: 4, name: "demo4.riff.cc", last_compile: nil, last_report: nil, updated_at: "2019-06-14 02:09:26", created_at: "2019-06-13 08:06:34", root_pass: "REDACTED...", architecture_id: 1, operatingsystem_id: 1, environment_id: 1, ptable_id: 103, medium_id: 10, build: true, comment: "", disk: "", installed_at: "2019-06-13 08:13:39", model_id: 1, hostgroup_id: nil, owner_id: 4, owner_type: "User", enabled: true, puppet_ca_proxy_id: 1, managed: true, use_image: nil, image_file: nil, uuid: nil, compute_resource_id: nil, puppet_proxy_id: 1, certname: "demo4.riff.cc", image_id: nil, organization_id: nil, location_id: nil, type: "Host::Managed", otp: nil, realm_id: nil, compute_profile_id: nil, provision_method: "build", grub_pass: "REDACTED...", global_status: 0, lookup_value_matcher: "fqdn=demo4.riff.cc", pxe_loader: "PXELinux BIOS", initiated_at: "2019-06-17 01:23:36", build_errors: nil>, @messages={:base=>["Create DHCP Settings for demo4.riff.cc task failed with the following error: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp", "Failed to perform rollback on Remove DHCP Settings for demo4.riff.cc - ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp"]}, @details={:base=>[{:error=>"Create DHCP Settings for demo4.riff.cc task failed with the following error: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp"}, {:error=>"Failed to perform rollback on Remove DHCP Settings for demo4.riff.cc - ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp"}]}>
2019-06-17T01:23:36 [E|app|6524c] Failed to save: Create DHCP Settings for demo4.riff.cc task failed with the following error: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp, Failed to perform rollback on Remove DHCP Settings for demo4.riff.cc - ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy https://fm-master2.riff.cc:8443/dhcp
2019-06-17T01:23:36 [I|app|6524c] Redirected to https://localhost:8443/hosts/demo4.riff.cc
2019-06-17T01:23:36 [I|app|6524c] Completed 302 Found in 748ms (ActiveRecord: 15.3ms)
2019-06-17T01:23:36 [I|app|] Started GET "/hosts/demo4.riff.cc" for 10.0.2.2 at 2019-06-17 01:23:36 +0000
2019-06-17T01:23:36 [I|app|d48c7] Processing by HostsController#show as HTML
2019-06-17T01:23:36 [I|app|d48c7]   Parameters: {"id"=>"demo4.riff.cc"}
2019-06-17T01:23:36 [I|app|d48c7] Current user set to admin (admin)
2019-06-17T01:23:36 [I|app|d48c7]   Rendering hosts/show.html.erb within layouts/application
2019-06-17T01:23:36 [I|app|d48c7]   Rendered hosts/_metrics.html.erb (0.1ms)
2019-06-17T01:23:36 [I|app|d48c7]   Rendered hosts/show.html.erb within layouts/application (16.3ms)
2019-06-17T01:23:36 [I|app|d48c7]   Rendered layouts/_application_content.html.erb (0.3ms)
2019-06-17T01:23:36 [I|app|d48c7]   Rendering layouts/base.html.erb
2019-06-17T01:23:36 [I|app|d48c7]   Rendered layouts/base.html.erb (9.0ms)
2019-06-17T01:23:36 [I|app|d48c7] Completed 200 OK in 38ms (Views: 25.5ms | ActiveRecord: 3.9ms)
2019-06-17T01:23:37 [I|app|] Started GET "/notification_recipients" for 10.0.2.2 at 2019-06-17 01:23:37 +0000
2019-06-17T01:23:37 [I|app|85029] Processing by NotificationRecipientsController#index as JSON
2019-06-17T01:23:37 [I|app|85029] Current user set to admin (admin)
2019-06-17T01:23:37 [D|not|85029] Cache Hit: notification, reading cache for notification-4
2019-06-17T01:23:37 [D|app|85029] Body: {"notifications":[{"id":34,"seen":false,"level":"info","text":"Merge time vs Change complexity in Foreman Core","created_at":"2019-06-16T06:45:44.691Z","group":"Community","actions":{"links":[{"href":"http://theforeman.org/2019/03/merge-time-review-complexity.html","title":"Open","external":true}]}},{"id":30,"seen":false,"level":"info","text":"Foreman Proxy Registration Protocol v2 explained","created_at":"2019-06-16T06:45:44.680Z","group":"Community","actions":{"links":[{"href":"http://theforeman.org/2019/04/smart-proxy-capabilities-explained.html","title":"Open","external":true}]}},{"id":26,"seen":false,"level":"info","text":"2019 Foreman Survey Analysis","created_at":"2019-06-16T06:45:44.658Z","group":"Community","actions":{"links":[{"href":"http://theforeman.org/2019/05/2019-foreman-survey-analysis.html","title":"Open","external":true}]}}]}
2019-06-17T01:23:37 [I|app|85029] Completed 200 OK in 5ms (Views: 0.2ms | ActiveRecord: 0.5ms)
2019-06-17T01:23:37 [I|app|] Started GET "/hosts/demo4.riff.cc/templates" for 10.0.2.2 at 2019-06-17 01:23:37 +0000
2019-06-17T01:23:37 [I|app|] Started GET "/hosts/demo4.riff.cc/runtime?range=7" for 10.0.2.2 at 2019-06-17 01:23:37 +0000
2019-06-17T01:23:37 [I|app|] Started GET "/hosts/demo4.riff.cc/nics" for 10.0.2.2 at 2019-06-17 01:23:37 +0000
2019-06-17T01:23:37 [I|app|59163] Processing by HostsController#runtime as HTML
2019-06-17T01:23:37 [I|app|] Started GET "/hosts/demo4.riff.cc/resources?range=7" for 10.0.2.2 at 2019-06-17 01:23:37 +0000
2019-06-17T01:23:37 [I|app|14818] Processing by HostsController#nics as HTML
2019-06-17T01:23:37 [I|app|f39cb] Processing by HostsController#templates as HTML
2019-06-17T01:23:37 [I|app|] Started GET "/hosts/demo4.riff.cc/overview" for 10.0.2.2 at 2019-06-17 01:23:37 +0000
2019-06-17T01:23:37 [I|app|59163]   Parameters: {"range"=>"7", "id"=>"demo4.riff.cc"}
2019-06-17T01:23:37 [I|app|14818]   Parameters: {"id"=>"demo4.riff.cc"}
2019-06-17T01:23:37 [I|app|f39cb]   Parameters: {"id"=>"demo4.riff.cc"}
2019-06-17T01:23:37 [I|app|14818] Current user set to admin (admin)
2019-06-17T01:23:37 [I|app|59163] Current user set to admin (admin)
2019-06-17T01:23:37 [I|app|f39cb] Current user set to admin (admin)
2019-06-17T01:23:37 [I|app|bb8fd] Processing by HostsController#overview as HTML
2019-06-17T01:23:37 [I|app|bb8fd]   Parameters: {"id"=>"demo4.riff.cc"}
2019-06-17T01:23:37 [I|app|bb8fd] Current user set to admin (admin)
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [I|app|49bb2] Processing by HostsController#resources as HTML
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [I|app|bb8fd]   Rendered hosts/_overview.html.erb (88.1ms)
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [I|app|bb8fd] Completed 200 OK in 136ms (Views: 34.1ms | ActiveRecord: 82.9ms)
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [I|app|49bb2]   Parameters: {"range"=>"7", "id"=>"demo4.riff.cc"}
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [I|app|59163]   Rendered hosts/_runtime.html.erb (176.5ms)
2019-06-17T01:23:37 [I|app|59163] Completed 200 OK in 271ms (Views: 198.8ms | ActiveRecord: 26.6ms)
2019-06-17T01:23:37 [D|app|f39cb] Current location set to none
2019-06-17T01:23:37 [D|app|f39cb] Current organization set to none
2019-06-17T01:23:37 [I|app|f39cb]   Rendered hosts/_templates.html.erb (31.4ms)
2019-06-17T01:23:37 [I|app|f39cb] Completed 200 OK in 298ms (Views: 10.4ms | ActiveRecord: 137.5ms)
2019-06-17T01:23:37 [I|app|14818]   Rendered hosts/_nics.html.erb (366.1ms)
2019-06-17T01:23:37 [I|app|49bb2] Current user set to admin (admin)
2019-06-17T01:23:37 [I|app|14818] Completed 200 OK in 422ms (Views: 347.0ms | ActiveRecord: 67.2ms)
2019-06-17T01:23:37 [I|app|49bb2]   Rendered hosts/_resources.html.erb (19.3ms)
2019-06-17T01:23:37 [I|app|49bb2] Completed 200 OK in 348ms (Views: 19.8ms | ActiveRecord: 43.2ms)
6

Can you do the same but from proxy (proxy.log)? Weird, I see that the record was deleted successfully and then creation fails. If it was deleted successfully than there should be nothing extra.

Are you using ISC DHCP? Can you also tail dhcpd.leases file and pastebin the changes there?

7

Here’s the log from proxy.log - https://paste.ubuntu.com/p/w2NxH6fVR2/

And yes, I’m using ISC DHCP, standard install w/ DHCP, DNS, TFTP.

There were no changes to the leases file - nothing showed up in my tail -F.

8

Also, I just stood up another Foreman instance on a new test machine and was able to replicate this issue exactly. Only difference is that one has the puppet server disabled. Other than that it was all the same.

9

For what it’s worth, this on an up-to-date install of Ubuntu Server 18.04.2, with nothing else on the box.

The following commands were used to install it -

foreman-installer \
  --enable-foreman-proxy \
  --foreman-proxy-tftp=true \
  --foreman-proxy-tftp-servername=10.21.30.3 \
  --foreman-proxy-dhcp=true \
  --foreman-proxy-dhcp-interface=enp0s8 \
  --foreman-proxy-dhcp-gateway="10.21.30.1" \
  --foreman-proxy-dhcp-nameservers="10.21.30.3" \
  --foreman-proxy-dns=true \
  --foreman-proxy-dns-interface=enp0s8 \
  --foreman-proxy-dns-zone=riff.cc \
  --foreman-proxy-dns-reverse=30.21.10.in-addr.arpa \
  --foreman-proxy-dns-forwarders=redacted.6 \
  --foreman-proxy-dns-forwarders=redacted.7 \
  --foreman-proxy-dns-forwarders=redacted.1 \
  --foreman-proxy-foreman-base-url=https://fm-master2.riff.cc
10

Hey,

smart proxy deletes the record successfully and moment after that it reports that there is an existing record with the very same MAC address. How can you tell that there were no changes made to the leases file? Are you sure this proxy is configured with ISC DHCP? There should be omshell debug statements in proxy.log showing communication with DHCP server.

Restart dhcpd and then go through /etc/dhcp/dhcpd.conf line by line, including all included configs and leases file - do you see that entry 08:00:27:83:11:8f somewhere? Haven’t someone added this via configuration file included from the main one?

11

I was doing tail -F /var/lib/dhcp/dhcpd.leases (I think that’s the path, not at work atm) and seeing no output.

I’m very sure it’s ISC DHCP, as I can manually delete the lease from that leases file and bounce isc-dhcpd-server and then try the action again and it works…

I’ll follow your suggestions tomorrow morning :slight_smile:

12

The question is not whether there is a ISC DHCP running on your server but rather if you have configured smart-proxy DHCP module with isc_dhcp provider. What is in your dhcp.yaml and dhcp_isc.yaml files?

If you are using ISC module then show me these debug lines in your proxy log:

You should see several of them every time you add or remove an entry.

13

I was able to replicate the issue at home.

These should hopefully be the same as my testbed at work.

I suspect I need to give the manual a good read.

dhcp.yml:

--
# Enable DHCP management
# Can be true, false, or http/https to enable just one of the protocols
:enabled: https

# valid providers:
#   - dhcp_isc (ISC dhcp server)
#   - dhcp_native_ms (Microsoft native implementation)
#   - dhcp_libvirt (dnsmasq via libvirt)
:use_provider: dhcp_isc
:server: 127.0.0.1
# subnets restricts the subnets queried to a subset, to reduce the query time.
#:subnets:
#  - 192.168.205.0/255.255.255.128
#  - 192.168.205.128/255.255.255.128

dhcp_isc.yml

---
#
# Configuration file for ISC dhcp provider
#

:config: /etc/dhcp/dhcpd.conf
:leases: /var/lib/dhcp/dhcpd.leases

# Redhat 5
#
#:config: /etc/dhcpd.conf
#
# Settings for Ubuntu
#
#:config: /etc/dhcp3/dhcpd.conf
#:leases: /var/lib/dhcp3/dhcpd.leases

# Specifies TSIG key name and secret

#:key_name: secret_key_name
#:key_secret: secret_key


:omapi_port: 7911

# use :server setting in dhcp.yml if you are managing a dhcp server which is not localhost

Restart dhcpd and then go through /etc/dhcp/dhcpd.conf line by line, including all included configs and leases file - do you see that entry 08:00:27:83:11:8f somewhere? Haven’t someone added this via configuration file included from the main one?

No, that entry only occurs in the leases file, and again if I manually delete that lease + bounce ISC, then retry the action (such as build etc) it is correctly recreated in the leases file and everything is fine. And this is now across 3 different installations, so it’s unlikely to be a manual screwup. Misconfiguration is now my guess.

14

If it would help, I’d be happy to recreate this problem on a DigitalOcean droplet and give you access to it to look around (and an exact list of commands I used to get it to that state). Obviously that’s not a “real” deployment but should be enough to debug this. I’m paying for a droplet anyways so it’s no additional cost to me.

Thanks for the patient help so far!

15

I see you haven’t used our installer for deployment, why? The DHCP configuration is pain in ass to configure manually. You are missing bunch of things, namely key_name and key_secret which allows you to connect to DHCP via omshell. The DHCP module does not open conf or lease file directly, it uses omshell command to do the updates which talks to the daemon using UNIX or TCP socket.

I recommend to install Foreman using our installer on a test box and then replicate the configuration if you insist on manual setup - that’s what I usually do. I am surprised this even booted up without those key configuration settings.

I can’t commit to taking a look directly, sorry.

16

I didn’t do any manual configuration, I used foreman-installer with the commands I mentioned earlier in the thread and then created the Subnet using the Foreman WebUI.

17

Ah - you mean run the interactive installer?

18

No, sorry I missed that you pasted it. @ekohl I see in Puppet codebase that key_name and key_secret can be also set to unset and then it is not put into the config file. Does it make sense to do it like that? I mean, why would anyone configure omapi without security? Can you tell @ekohl why installer would not set those?

Anyway, I tested creation of host without those key/secret set and I am getting an error:

2019-06-18T15:42:40 091ffc1b [W] Failed to add DHCP reservation for jay-depugh.nat.lan (192.168.99.155 / 52:54:00:60:60:01): No response from DHCP server
Proxy::DHCP::Error: Failed to add DHCP reservation for jay-depugh.nat.lan (192.168.99.155 / 52:54:00:60:60:01): No response from DHCP server
/home/lzap/work/smart-proxy/modules/dhcp_common/isc/omapi_provider.rb:103:in `report'
/home/lzap/work/smart-proxy/modules/dhcp_common/isc/omapi_provider.rb:81:in `om_disconnect'
/home/lzap/work/smart-proxy/modules/dhcp_common/isc/omapi_provider.rb:54:in `om_add_record'
/home/lzap/work/smart-proxy/modules/dhcp_common/isc/omapi_provider.rb:30:in `add_record'

I am wrapping up earlier today, try me (lzap) on IRC tomorrow morning and I can probably take a look on your instance. This is weird.

19

The plot thickens even further…

I took some debug logs of creating a machine, which works fine…

Proxy: https://paste.ubuntu.com/p/5KpCYsCntd/
Production: https://paste.ubuntu.com/p/j9qbkw3dMj/

And suddenly omshell commands show up, such as

omshell: executed - set statements = "filename = \"pxelinux.0\"; next-server = 0a:15:1e:03; option host-name = \"demo11.riff.cc\";"
20

That’s what is expected. What is the current issue then? You must see them when doing edit as well. Maybe foreman-proxy was not restarted?