Project

General

Profile

Bug #17823

Non-JSON response from MS DNS record deletion

Added by Alex Brodov over 4 years ago. Updated almost 3 years ago.

Status:
Closed
Priority:
Normal
Assignee:
Category:
DNS
Target version:
Difficulty:
Triaged:
Bugzilla link:
Fixed in Releases:
Found in Releases:

Description

I'm using Foreman 1.13.2 and smart proxy with MS DHCP and MS DNS.

When I'm trying to delete the host for the first time i'm getting an error (below), the 2nd time i click the delete button it's working:

Oops, we're sorry but something went wrong Failed to destroy the record

Below is the relevant part from the log:


2016-12-22 00:22:19 e6c4c4ba [app] [I] Delete the DNS A record for alex-12.mydomain.com/172.29.20.135
2016-12-22 00:22:20 e6c4c4ba [app] [I] Delete the DNS PTR record for 172.29.20.135/alex-12.mydomain.com
2016-12-22 00:22:20 e6c4c4ba [app] [I] Delete DHCP reservation for alex-12.mydomain.com-00:50:56:8c:a3:9b/172.29.20.135
2016-12-22 00:22:20 e6c4c4ba [app] [W] Failed to parse response:
 | Changed the current scope context to 172.29.20.0 scope.
 |
 | Command completed successfully.
 |  -> 757: unexpected token at 'Changed the current scope context to 172.29.20.0 scope.
 |
 | Command completed successfully.
 | '
2016-12-22 00:22:20 e6c4c4ba [app] [I] Add DNS PTR record for 172.29.20.135/alex-12.mydomain.com
2016-12-22 00:22:21 e6c4c4ba [app] [I] Add DNS A record for alex-12.mydomain.com/172.29.20.135
2016-12-22 00:22:21 e6c4c4ba [app] [W] Action failed
 | ActiveRecord::RecordNotDestroyed: Failed to destroy the record
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/persistence.rb:185:in `destroy!'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/has_many_association.rb:171:in `each'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/has_many_association.rb:171:in `delete_records'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:525:in `remove_records'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:518:in `block in delete_or_destroy'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:183:in `block in transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/database_statements.rb:211:in `transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:220:in `transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:182:in `transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:518:in `delete_or_destroy'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:279:in `destroy'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/collection_association.rb:223:in `destroy_all'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/has_many_association.rb:27:in `handle_dependency'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/associations/builder/association.rb:146:in `block in add_destroy_callbacks'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:448:in `instance_exec'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:448:in `block in make_lambda'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:164:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:164:in `block in halting'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `block in call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `each'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:504:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:92:in `__run_callbacks__'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:778:in `_run_destroy_callbacks'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/callbacks.rb:292:in `destroy'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:281:in `block in destroy'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:351:in `block in with_transaction_returning_status'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/database_statements.rb:213:in `block in transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/transaction.rb:184:in `within_new_transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/database_statements.rb:213:in `transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:220:in `transaction'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:348:in `with_transaction_returning_status'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/transactions.rb:281:in `destroy'
 | /usr/share/foreman/app/controllers/hosts_controller.rb:122:in `destroy'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/abstract_controller/base.rb:198:in `process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/rendering.rb:10:in `process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:117:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:117:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:555:in `block (2 levels) in compile'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `block (2 levels) in halting'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/rails-observers-0.1.2/lib/rails/observers/action_controller/caching/sweeping.rb:73:in `around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:455:in `public_send'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:455:in `block in make_lambda'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `block in halting'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `block in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `block (2 levels) in halting'
 | /usr/share/foreman/app/controllers/concerns/application_shared.rb:14:in `set_timezone'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:432:in `block in make_lambda'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `block in halting'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `block in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `block (2 levels) in halting'
 | /usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:432:in `block in make_lambda'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `block in halting'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `block in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:313:in `block (2 levels) in halting'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/rails-observers-0.1.2/lib/rails/observers/action_controller/caching/sweeping.rb:73:in `around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:455:in `public_send'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:455:in `block in make_lambda'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:312:in `block in halting'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:497:in `block in around'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:92:in `__run_callbacks__'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:778:in `_run_process_action_callbacks'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:81:in `run_callbacks'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/abstract_controller/callbacks.rb:19:in `process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/rescue.rb:29:in `process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/notifications.rb:164:in `block in instrument'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/notifications.rb:164:in `instrument'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/params_wrapper.rb:250:in `process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/abstract_controller/base.rb:137:in `process'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionview-4.2.5.1/lib/action_view/rendering.rb:30:in `process'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal.rb:196:in `dispatch'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_controller/metal.rb:237:in `block in action'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/routing/route_set.rb:74:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/routing/route_set.rb:74:in `dispatch'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/routing/route_set.rb:43:in `serve'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/journey/router.rb:43:in `block in serve'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/journey/router.rb:30:in `each'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/journey/router.rb:30:in `serve'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/routing/route_set.rb:815:in `call'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.3.6/lib/apipie/static_dispatcher.rb:65:in `call'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.3.6/lib/apipie/extractor/recorder.rb:132:in `call'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.3.6/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/etag.rb:24:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/conditionalget.rb:38:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/head.rb:13:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/params_parser.rb:27:in `call'
 | /usr/share/foreman/lib/middleware/catch_json_parse_errors.rb:9:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/flash.rb:260:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/session/abstract/id.rb:225:in `context'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/session/abstract/id.rb:220:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/cookies.rb:560:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/query_cache.rb:36:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activerecord-4.2.5.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:653:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:88:in `__run_callbacks__'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:778:in `_run_call_callbacks'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/callbacks.rb:81:in `run_callbacks'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/remote_ip.rb:78:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/railties-4.2.5.1/lib/rails/rack/logger.rb:38:in `call_app'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/railties-4.2.5.1/lib/rails/rack/logger.rb:22:in `call'
 | /usr/share/foreman/lib/middleware/tagged_logging.rb:18:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/request_id.rb:21:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/methodoverride.rb:22:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/runtime.rb:18:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/activesupport-4.2.5.1/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/actionpack-4.2.5.1/lib/action_dispatch/middleware/static.rb:116:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/sendfile.rb:113:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/railties-4.2.5.1/lib/rails/engine.rb:518:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/railties-4.2.5.1/lib/rails/application.rb:165:in `call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/railties-4.2.5.1/lib/rails/railtie.rb:194:in `public_send'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/railties-4.2.5.1/lib/rails/railtie.rb:194:in `method_missing'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/urlmap.rb:66:in `block in call'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/urlmap.rb:50:in `each'
 | /opt/rh/sclo-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/urlmap.rb:50:in `call'
 | /usr/share/passenger/phusion_passenger/rack/thread_handler_extension.rb:74:in `process_request'
 | /usr/share/passenger/phusion_passenger/request_handler/thread_handler.rb:141:in `accept_and_process_next_request'
 | /usr/share/passenger/phusion_passenger/request_handler/thread_handler.rb:109:in `main_loop'
 | /usr/share/passenger/phusion_passenger/request_handler.rb:455:in `block (3 levels) in start_threads'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `call'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'
2016-12-22 00:22:21 e6c4c4ba [app] [I]   Rendered common/500.html.erb within layouts/application (4.5ms)
2016-12-22 00:22:21 e6c4c4ba [app] [I]   Rendered layouts/_application_content.html.erb (0.2ms)
2016-12-22 00:22:21 e6c4c4ba [app] [I]   Rendered layouts/base.html.erb (1.4ms)
2016-12-22 00:22:21 e6c4c4ba [app] [I] Completed 500 Internal Server Error in 1330ms (Views: 7.1ms | ActiveRecord: 2.5ms)

Here's the log from the 2nd attempt:

2016-12-22 00:31:04 e6c4c4ba [app] [I] Started DELETE "/hosts/alex-12.mydomain.com" for 10.10.40.7 at 2016-12-22 00:31:04 +0000
2016-12-22 00:31:04 e6c4c4ba [app] [I] Processing by HostsController#destroy as HTML
2016-12-22 00:31:04 e6c4c4ba [app] [I]   Parameters: {"authenticity_token"=>"3LGF/OKcqCqgA4NVeJ4IkQ9PAua7RlKRBX3XyfChdoNveHZtU1sfD+HrfpKNVjlhi1XIYDB7pcf+DQXwjFYQ2Q==", "id"=>"alex-12.mydomain.com"}
2016-12-22 00:31:04 e6c4c4ba [app] [I] Delete the DNS A record for alex-12.mydomain.com/172.29.20.135
2016-12-22 00:31:05 e6c4c4ba [app] [I] Delete the DNS PTR record for 172.29.20.135/alex-12.mydomain.com
2016-12-22 00:31:05 e6c4c4ba [app] [I] Delete DHCP reservation for alex-12.mydomain.com-00:50:56:8c:a3:9b/172.29.20.135
2016-12-22 00:31:08 e6c4c4ba [app] [I] Redirected to https://do-foreman.mydomain.com/hosts
2016-12-22 00:31:08 e6c4c4ba [app] [I] Completed 302 Found in 3560ms (ActiveRecord: 7.4ms)
2016-12-22 00:31:08 e6c4c4ba [app] [I] Started GET "/hosts" for 10.10.40.7 at 2016-12-22 00:31:08 +0000
2016-12-22 00:31:08 e6c4c4ba [app] [I] Processing by HostsController#index as HTML
2016-12-22 00:31:08 e6c4c4ba [app] [I]   Rendered hosts/_list.html.erb (11.3ms)
2016-12-22 00:31:08 e6c4c4ba [app] [I]   Rendered hosts/index.html.erb within layouts/application (16.6ms)
2016-12-22 00:31:08 e6c4c4ba [app] [I]   Rendered common/_searchbar.html.erb (9.0ms)
2016-12-22 00:31:08 e6c4c4ba [app] [I]   Rendered layouts/_application_content.html.erb (9.3ms)
2016-12-22 00:31:08 e6c4c4ba [app] [I]   Rendered home/_user_dropdown.html.erb (1.6ms)
2016-12-22 00:31:08 e6c4c4ba [app] [I] Read fragment views/tabs_and_title_records-4 (0.1ms)
2016-12-22 00:31:08 e6c4c4ba [app] [I]   Rendered home/_topbar.html.erb (4.3ms)
2016-12-22 00:31:08 e6c4c4ba [app] [I]   Rendered layouts/base.html.erb (5.8ms)
2016-12-22 00:31:08 e6c4c4ba [app] [I] Completed 200 OK in 58ms (Views: 31.3ms | ActiveRecord: 5.3ms)

It seems like it can't parse the response from destroy command

2016-12-22 00:22:20 e6c4c4ba [app] [W] Failed to parse response:
 | Changed the current scope context to 172.29.20.0 scope.
 |
 | Command completed successfully.
 |  -> 757: unexpected token at 'Changed the current scope context to 172.29.20.0 scope.
 |
 | Command completed successfully.
 | '

Related issues

Has duplicate Foreman - Bug #18074: "Failed to destroy the record" error while deleting hostDuplicate2017-01-13

History

#1 Updated by Alex Brodov over 4 years ago

  • Description updated (diff)

#2 Updated by Dominic Cleal over 4 years ago

  • Project changed from Foreman to Smart Proxy
  • Subject changed from Unable to delete host to Non-JSON response from MS DNS record deletion
  • Category changed from DNS to DNS

Which version of the smart proxy are you using? Please ensure it's also up to date, this looks a bit like it may have been fixed in #13536 (1.12.0).

#3 Updated by Alex Brodov over 4 years ago

Dominic Cleal wrote:

Which version of the smart proxy are you using? Please ensure it's also up to date, this looks a bit like it may have been fixed in #13536 (1.12.0).

I'm using version: 1.13.0...
Seems like the bug still exists in the current version.

#4 Updated by Alex Brodov over 4 years ago

Dominic Cleal wrote:

Which version of the smart proxy are you using? Please ensure it's also up to date, this looks a bit like it may have been fixed in #13536 (1.12.0).

I've just updated to 1.13.3 which is the stable version.

The bug still exists, I'm trying to debug the MS DHCP behavior, the thing is that the parse method is somehow getting the output of the 'netsh' command (as we can see the record got deleted from DHCP).

#5 Updated by Dmitri Dolguikh over 4 years ago

Could you enable debug logging on the smart-proxy and post the log of the failing call here?

#6 Updated by Alex Brodov over 4 years ago

Dmitri Dolguikh wrote:

Could you enable debug logging on the smart-proxy and post the log of the failing call here?

Below is the log from the smart proxy log of the first try:

D, [2016-12-25T17:17:25.143990 #2636] DEBUG -- : verifying remote client 172.29.20.226 against trusted_hosts ["do-foreman.mydomain.com", "uslabdns1.mydomain.com"]
D, [2016-12-25T17:17:25.143990 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\dnscmd.exe localhost /EnumZones
D, [2016-12-25T17:17:25.175241 #2636] DEBUG -- : Enumerated authoritative dns zones: ["20.29.172.in-addr.arpa", "mydomain.com", "TrustAnchors"]
D, [2016-12-25T17:17:25.175241 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\dnscmd.exe localhost /RecordDelete mydomain.com demo-4man.mydomain.com. A /f
D, [2016-12-25T17:17:25.222117 #2636] DEBUG -- : Removed DNS entry demo-4man.mydomain.com
I, [2016-12-25T17:17:25.237744 #2636]  INFO -- : 172.29.20.226 - - [25/Dec/2016 17:17:25] "DELETE /dns/demo-4man.mydomain.com/A HTTP/1.1" 200 - 0.0938

D, [2016-12-25T17:17:25.237744 #2636] DEBUG -- : close: 172.29.20.226:38433
D, [2016-12-25T17:17:25.300243 #2636] DEBUG -- : accept: 172.29.20.226:38434
D, [2016-12-25T17:17:25.300243 #2636] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2016-12-25T17:17:25.300243 #2636] DEBUG -- : verifying remote client 172.29.20.226 against trusted_hosts ["do-foreman.mydomain.com", "uslabdns1.mydomain.com"]
D, [2016-12-25T17:17:25.300243 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\dnscmd.exe localhost /EnumZones
D, [2016-12-25T17:17:25.331495 #2636] DEBUG -- : Enumerated authoritative dns zones: ["20.29.172.in-addr.arpa", "mydomain.com", "TrustAnchors"]
D, [2016-12-25T17:17:25.331495 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\dnscmd.exe localhost /RecordDelete 20.29.172.in-addr.arpa 159.20.29.172.in-addr.arpa. PTR /f
D, [2016-12-25T17:17:25.378371 #2636] DEBUG -- : Removed PTR entry 159.20.29.172.in-addr.arpa
I, [2016-12-25T17:17:25.378371 #2636]  INFO -- : 172.29.20.226 - - [25/Dec/2016 17:17:25] "DELETE /dns/159.20.29.172.in-addr.arpa HTTP/1.1" 200 - 0.0781

D, [2016-12-25T17:17:25.409656 #2636] DEBUG -- : close: 172.29.20.226:38434
D, [2016-12-25T17:17:25.519001 #2636] DEBUG -- : accept: 172.29.20.226:38436
D, [2016-12-25T17:17:25.534626 #2636] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2016-12-25T17:17:25.534626 #2636] DEBUG -- : verifying remote client 172.29.20.226 against trusted_hosts ["do-foreman.mydomain.com", "uslabdns1.mydomain.com"]
D, [2016-12-25T17:17:25.534626 #2636] DEBUG -- : Loading subnets for 127.0.0.1
D, [2016-12-25T17:17:25.534626 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.0.0.1 show scope
D, [2016-12-25T17:17:25.753383 #2636] DEBUG -- : Enumerated the scopes on 127.0.0.1
D, [2016-12-25T17:17:25.753383 #2636] DEBUG -- : Added a subnet: 172.29.20.0
D, [2016-12-25T17:17:25.753383 #2636] DEBUG -- : Loading subnet data for 172.29.20.0/255.255.255.0
D, [2016-12-25T17:17:25.753383 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.0.0.1 scope 172.29.20.0 show client 1
D, [2016-12-25T17:17:25.878385 #2636] DEBUG -- : Enumerated hosts on 172.29.20.0
D, [2016-12-25T17:17:25.878385 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.100", :mac=>"00:50:56:8c:3a:7d", :name=>"smart-proxy.mydomain.com"}
D, [2016-12-25T17:17:25.878385 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.103", :mac=>"00:50:56:8c:61:ed", :name=>"alex-local-dev.mydomain.com"}
D, [2016-12-25T17:17:25.878385 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.104", :mac=>"00:50:56:8c:d8:40", :name=>"vaai55.mydomain.com"}
D, [2016-12-25T17:17:25.878385 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.105", :mac=>"00:50:56:8c:40:2d", :name=>"ssb3.mydomain.com"}
D, [2016-12-25T17:17:25.878385 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.106", :mac=>"00:50:56:8c:b3:32", :name=>"ssb1.mydomain.com"}
D, [2016-12-25T17:17:25.878385 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.107", :mac=>"00:50:56:8c:4d:53", :name=>""}
D, [2016-12-25T17:17:25.878385 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.108", :mac=>"00:50:56:8c:4d:eb", :name=>""}
D, [2016-12-25T17:17:25.878385 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.109", :mac=>"00:50:56:8c:d7:e9", :name=>"ssb2.mydomain.com"}
D, [2016-12-25T17:17:25.878385 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.110", :mac=>"32:2f:41:83:dd:ea", :name=>""}
D, [2016-12-25T17:17:25.878385 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.156", :mac=>"00:50:56:8c:db:d3", :name=>"alex-4man.mydomain.com"}
D, [2016-12-25T17:17:25.878385 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.157", :mac=>"00:50:56:8c:b2:67", :name=>"demo-host-4man.mydomain.com"}
D, [2016-12-25T17:17:25.878385 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.159", :mac=>"00:50:56:8c:5f:ee", :name=>"demo-4man.mydomain.com"}
D, [2016-12-25T17:17:25.878385 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.0.0.1 scope 172.29.20.0 Show ReservedOptionValue 172.29.20.159
D, [2016-12-25T17:17:25.987761 #2636] DEBUG -- : Queried 172.29.20.159 options
D, [2016-12-25T17:17:25.987761 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.170", :mac=>"00:50:56:8c:5f:09", :name=>"api-local-test-2.mydomain.com"}
D, [2016-12-25T17:17:25.987761 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.172", :mac=>"00:50:56:8c:56:1e", :name=>"4man-test-3.mydomain.com"}
D, [2016-12-25T17:17:25.987761 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.179", :mac=>"00:50:56:8c:9b:e7", :name=>"api-local-test-5.mydomain.com"}
D, [2016-12-25T17:17:25.987761 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000001c334e8 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:17:25 -0700>, :ip=>"172.29.20.226", :mac=>"00:50:56:8c:17:9b", :name=>"do-foreman.mydomain.com"}
D, [2016-12-25T17:17:25.987761 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.0.0.1 scope 172.29.20.0 Show ReservedOptionValue 172.29.20.226
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Queried 172.29.20.226 options
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a lease record: 172.29.20.100:00:50:56:8c:3a:7d
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a lease record: 172.29.20.103:00:50:56:8c:61:ed
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a lease record: 172.29.20.104:00:50:56:8c:d8:40
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a lease record: 172.29.20.105:00:50:56:8c:40:2d
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a lease record: 172.29.20.106:00:50:56:8c:b3:32
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a lease record: 172.29.20.107:00:50:56:8c:4d:53
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a lease record: 172.29.20.108:00:50:56:8c:4d:eb
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a lease record: 172.29.20.109:00:50:56:8c:d7:e9
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a lease record: 172.29.20.110:32:2f:41:83:dd:ea
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a lease record: 172.29.20.156:00:50:56:8c:db:d3
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a lease record: 172.29.20.157:00:50:56:8c:b2:67
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a reservation: 172.29.20.159:00:50:56:8c:5f:ee:demo-4man.mydomain.com
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a lease record: 172.29.20.170:00:50:56:8c:5f:09
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a lease record: 172.29.20.172:00:50:56:8c:56:1e
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a lease record: 172.29.20.179:00:50:56:8c:9b:e7
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : Added a reservation: 172.29.20.226:00:50:56:8c:17:9b:do-foreman.mydomain.com
D, [2016-12-25T17:17:26.081517 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.0.0.1 scope 172.29.20.0 delete reservedip 172.29.20.159 0050568c5fee
D, [2016-12-25T17:17:26.190893 #2636] DEBUG -- : Removed DHCP reservation for demo-4man.mydomain.com => 172.29.20.159 - 00:50:56:8c:5f:ee
I, [2016-12-25T17:17:26.190893 #2636]  INFO -- : 172.29.20.226 - - [25/Dec/2016 17:17:26] "DELETE /dhcp/172.29.20.0/00:50:56:8c:5f:ee HTTP/1.1" 200 90 0.6563

D, [2016-12-25T17:17:26.237817 #2636] DEBUG -- : close: 172.29.20.226:38436
D, [2016-12-25T17:17:26.284644 #2636] DEBUG -- : accept: 172.29.20.226:38437
D, [2016-12-25T17:17:26.300272 #2636] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2016-12-25T17:17:26.300272 #2636] DEBUG -- : verifying remote client 172.29.20.226 against trusted_hosts ["do-foreman.mydomain.com", "uslabdns1.mydomain.com"]
D, [2016-12-25T17:17:26.300272 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\dnscmd.exe localhost /EnumZones
D, [2016-12-25T17:17:26.347147 #2636] DEBUG -- : Enumerated authoritative dns zones: ["20.29.172.in-addr.arpa", "mydomain.com", "TrustAnchors"]
D, [2016-12-25T17:17:26.347147 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\dnscmd.exe localhost /RecordAdd 20.29.172.in-addr.arpa 159.20.29.172.in-addr.arpa. PTR demo-4man.mydomain.com.
D, [2016-12-25T17:17:26.378397 #2636] DEBUG -- : Added PTR entry 159.20.29.172.in-addr.arpa => demo-4man.mydomain.com
I, [2016-12-25T17:17:26.378397 #2636]  INFO -- : 172.29.20.226 - - [25/Dec/2016 17:17:26] "POST /dns/ HTTP/1.1" 200 - 0.0781

D, [2016-12-25T17:17:26.394066 #2636] DEBUG -- : close: 172.29.20.226:38437
D, [2016-12-25T17:17:26.425271 #2636] DEBUG -- : accept: 172.29.20.226:38438
D, [2016-12-25T17:17:26.440898 #2636] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2016-12-25T17:17:26.440898 #2636] DEBUG -- : verifying remote client 172.29.20.226 against trusted_hosts ["do-foreman.mydomain.com", "uslabdns1.mydomain.com"]
D, [2016-12-25T17:17:26.440898 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\dnscmd.exe localhost /EnumZones
D, [2016-12-25T17:17:26.472150 #2636] DEBUG -- : Enumerated authoritative dns zones: ["20.29.172.in-addr.arpa", "mydomain.com", "TrustAnchors"]
D, [2016-12-25T17:17:26.472150 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\dnscmd.exe localhost /RecordAdd mydomain.com demo-4man.mydomain.com. A 172.29.20.159
D, [2016-12-25T17:17:26.519024 #2636] DEBUG -- : Added DNS entry demo-4man.mydomain.com => 172.29.20.159
I, [2016-12-25T17:17:26.519024 #2636]  INFO -- : 172.29.20.226 - - [25/Dec/2016 17:17:26] "POST /dns/ HTTP/1.1" 200 - 0.0781

D, [2016-12-25T17:17:26.534692 #2636] DEBUG -- : close: 172.29.20.226:38438

Here's the log from the second attempt:

D, [2016-12-25T17:17:26.394066 #2636] DEBUG -- : close: 172.29.20.226:38437
D, [2016-12-25T17:17:26.425271 #2636] DEBUG -- : accept: 172.29.20.226:38438
D, [2016-12-25T17:17:26.440898 #2636] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2016-12-25T17:17:26.440898 #2636] DEBUG -- : verifying remote client 172.29.20.226 against trusted_hosts ["do-foreman.mydomain.com", "uslabdns1.mydomain.com"]
D, [2016-12-25T17:17:26.440898 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\dnscmd.exe localhost /EnumZones
D, [2016-12-25T17:17:26.472150 #2636] DEBUG -- : Enumerated authoritative dns zones: ["20.29.172.in-addr.arpa", "mydomain.com", "TrustAnchors"]
D, [2016-12-25T17:17:26.472150 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\dnscmd.exe localhost /RecordAdd mydomain.com demo-4man.mydomain.com. A 172.29.20.159
D, [2016-12-25T17:17:26.519024 #2636] DEBUG -- : Added DNS entry demo-4man.mydomain.com => 172.29.20.159
I, [2016-12-25T17:17:26.519024 #2636]  INFO -- : 172.29.20.226 - - [25/Dec/2016 17:17:26] "POST /dns/ HTTP/1.1" 200 - 0.0781

D, [2016-12-25T17:17:26.534692 #2636] DEBUG -- : close: 172.29.20.226:38438
D, [2016-12-25T17:27:45.020444 #2636] DEBUG -- : accept: 172.29.20.226:38447
D, [2016-12-25T17:27:45.036071 #2636] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2016-12-25T17:27:45.036071 #2636] DEBUG -- : verifying remote client 172.29.20.226 against trusted_hosts ["do-foreman.mydomain.com", "uslabdns1.mydomain.com"]
D, [2016-12-25T17:27:45.036071 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\dnscmd.exe localhost /EnumZones
D, [2016-12-25T17:27:45.082951 #2636] DEBUG -- : Enumerated authoritative dns zones: ["20.29.172.in-addr.arpa", "mydomain.com", "TrustAnchors"]
D, [2016-12-25T17:27:45.082951 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\dnscmd.exe localhost /RecordDelete mydomain.com demo-4man.mydomain.com. A /f
D, [2016-12-25T17:27:45.114199 #2636] DEBUG -- : Removed DNS entry demo-4man.mydomain.com
I, [2016-12-25T17:27:45.114199 #2636]  INFO -- : 172.29.20.226 - - [25/Dec/2016 17:27:45] "DELETE /dns/demo-4man.mydomain.com/A HTTP/1.1" 200 - 0.0781

D, [2016-12-25T17:27:45.145483 #2636] DEBUG -- : close: 172.29.20.226:38447
D, [2016-12-25T17:27:45.192323 #2636] DEBUG -- : accept: 172.29.20.226:38448
D, [2016-12-25T17:27:45.192323 #2636] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2016-12-25T17:27:45.192323 #2636] DEBUG -- : verifying remote client 172.29.20.226 against trusted_hosts ["do-foreman.mydomain.com", "uslabdns1.mydomain.com"]
D, [2016-12-25T17:27:45.192323 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\dnscmd.exe localhost /EnumZones
D, [2016-12-25T17:27:45.239201 #2636] DEBUG -- : Enumerated authoritative dns zones: ["20.29.172.in-addr.arpa", "mydomain.com", "TrustAnchors"]
D, [2016-12-25T17:27:45.239201 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\dnscmd.exe localhost /RecordDelete 20.29.172.in-addr.arpa 159.20.29.172.in-addr.arpa. PTR /f
D, [2016-12-25T17:27:45.286078 #2636] DEBUG -- : Removed PTR entry 159.20.29.172.in-addr.arpa
I, [2016-12-25T17:27:45.286078 #2636]  INFO -- : 172.29.20.226 - - [25/Dec/2016 17:27:45] "DELETE /dns/159.20.29.172.in-addr.arpa HTTP/1.1" 200 - 0.0938

D, [2016-12-25T17:27:45.301718 #2636] DEBUG -- : close: 172.29.20.226:38448
D, [2016-12-25T17:27:45.442330 #2636] DEBUG -- : accept: 172.29.20.226:38450
D, [2016-12-25T17:27:45.442330 #2636] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2016-12-25T17:27:45.442330 #2636] DEBUG -- : verifying remote client 172.29.20.226 against trusted_hosts ["do-foreman.mydomain.com", "uslabdns1.mydomain.com"]
D, [2016-12-25T17:27:45.442330 #2636] DEBUG -- : Loading subnets for 127.0.0.1
D, [2016-12-25T17:27:45.442330 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.0.0.1 show scope
D, [2016-12-25T17:27:45.551710 #2636] DEBUG -- : Enumerated the scopes on 127.0.0.1
D, [2016-12-25T17:27:45.551710 #2636] DEBUG -- : Added a subnet: 172.29.20.0
D, [2016-12-25T17:27:45.551710 #2636] DEBUG -- : Loading subnet data for 172.29.20.0/255.255.255.0
D, [2016-12-25T17:27:45.551710 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.0.0.1 scope 172.29.20.0 show client 1
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : Enumerated hosts on 172.29.20.0
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.100", :mac=>"00:50:56:8c:3a:7d", :name=>"smart-proxy.mydomain.com"}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.103", :mac=>"00:50:56:8c:61:ed", :name=>"alex-local-dev.mydomain.com"}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.104", :mac=>"00:50:56:8c:d8:40", :name=>"vaai55.mydomain.com"}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.105", :mac=>"00:50:56:8c:40:2d", :name=>"ssb3.mydomain.com"}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.106", :mac=>"00:50:56:8c:b3:32", :name=>"ssb1.mydomain.com"}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.107", :mac=>"00:50:56:8c:4d:53", :name=>""}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.108", :mac=>"00:50:56:8c:4d:eb", :name=>""}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.109", :mac=>"00:50:56:8c:d7:e9", :name=>"ssb2.mydomain.com"}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.110", :mac=>"32:2f:41:83:dd:ea", :name=>""}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.156", :mac=>"00:50:56:8c:db:d3", :name=>"alex-4man.mydomain.com"}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.157", :mac=>"00:50:56:8c:b2:67", :name=>"demo-host-4man.mydomain.com"}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.159", :mac=>"00:50:56:8c:5f:ee", :name=>"demo-4man.mydomain.com"}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.170", :mac=>"00:50:56:8c:5f:09", :name=>"api-local-test-2.mydomain.com"}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.172", :mac=>"00:50:56:8c:56:1e", :name=>"4man-test-3.mydomain.com"}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.179", :mac=>"00:50:56:8c:9b:e7", :name=>"api-local-test-5.mydomain.com"}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : {:subnet=>#<Proxy::DHCP::Subnet:0x00000002d7a210 @network="172.29.20.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:172.29.20.0/255.255.255.0>, @options={}, @timestamp=2016-12-25 17:27:45 -0700>, :ip=>"172.29.20.226", :mac=>"00:50:56:8c:17:9b", :name=>"do-foreman.mydomain.com"}
D, [2016-12-25T17:27:45.676715 #2636] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.0.0.1 scope 172.29.20.0 Show ReservedOptionValue 172.29.20.226
D, [2016-12-25T17:27:45.786092 #2636] DEBUG -- : Queried 172.29.20.226 options
D, [2016-12-25T17:27:45.786092 #2636] DEBUG -- : Added a lease record: 172.29.20.100:00:50:56:8c:3a:7d
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : Added a lease record: 172.29.20.103:00:50:56:8c:61:ed
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : Added a lease record: 172.29.20.104:00:50:56:8c:d8:40
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : Added a lease record: 172.29.20.105:00:50:56:8c:40:2d
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : Added a lease record: 172.29.20.106:00:50:56:8c:b3:32
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : Added a lease record: 172.29.20.107:00:50:56:8c:4d:53
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : Added a lease record: 172.29.20.108:00:50:56:8c:4d:eb
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : Added a lease record: 172.29.20.109:00:50:56:8c:d7:e9
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : Added a lease record: 172.29.20.110:32:2f:41:83:dd:ea
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : Added a lease record: 172.29.20.156:00:50:56:8c:db:d3
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : Added a lease record: 172.29.20.157:00:50:56:8c:b2:67
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : Added a lease record: 172.29.20.159:00:50:56:8c:5f:ee
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : Added a lease record: 172.29.20.170:00:50:56:8c:5f:09
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : Added a lease record: 172.29.20.172:00:50:56:8c:56:1e
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : Added a lease record: 172.29.20.179:00:50:56:8c:9b:e7
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : Added a reservation: 172.29.20.226:00:50:56:8c:17:9b:do-foreman.mydomain.com
E, [2016-12-25T17:27:45.801719 #2636] ERROR -- : DHCP record 172.29.20.0/00:50:56:8c:5f:ee not found
D, [2016-12-25T17:27:45.801719 #2636] DEBUG -- : DHCP record 172.29.20.0/00:50:56:8c:5f:ee not found
I, [2016-12-25T17:27:45.801719 #2636]  INFO -- : 172.29.20.226 - - [25/Dec/2016 17:27:45] "DELETE /dhcp/172.29.20.0/00:50:56:8c:5f:ee HTTP/1.1" 404 51 0.3594

D, [2016-12-25T17:27:45.848603 #2636] DEBUG -- : close: 172.29.20.226:38450

There's another issue, on the first attempt as you can see, after the DHCP record deletion, it's adding back the DNS records (A & PTR), I'm assuming it's due to the exception which is raised on the Foreman side.

#7 Updated by Dmitri Dolguikh over 4 years ago

I don't see any errors in the first log. The second attempt shows a failure to delete a host with mac 00:50:56:8c:5f:ee: it's a lease and 1.13 doesn't support removal of lease records. I would suggest to try using 1.14 or develop -- you won't see parsing errors, and removal of lease records is supported in those versions.

#8 Updated by Alex Brodov over 4 years ago

Dmitri Dolguikh wrote:

I don't see any errors in the first log. The second attempt shows a failure to delete a host with mac 00:50:56:8c:5f:ee: it's a lease and 1.13 doesn't support removal of lease records. I would suggest to try using 1.14 or develop -- you won't see parsing errors, and removal of lease records is supported in those versions.

Is it going to be enough to use smart proxy 1.14?
We can clearly see that the smart proxy is succeeding to remove in the first attempt, but it's returning the stdout of the dhcp delete execution, and this can't be parsed by the foreman side, maybe we can disable the stdout on the smart proxy side?

#9 Updated by Dmitri Dolguikh over 4 years ago

Is it going to be enough to use smart proxy 1.14?

I'm not sure what you mean.

You can try getting 1.13 to work. Large changes won't be accepted into 1.13 at this point however, and 1.14 has a completely new implementation of MS dhcp interface -- any 1.13 fixes will not be applicable to it.

#10 Updated by Dmitri Dolguikh over 4 years ago

I should mention that 1.14 solves a few issues present in the original implementation of MS dhcp interface, and if the intention is to use your setup in production, you'd probably be better of with 1.14 and above.

#11 Updated by Alex Brodov over 4 years ago

Dmitri Dolguikh wrote:

I should mention that 1.14 solves a few issues present in the original implementation of MS dhcp interface, and if the intention is to use your setup in production, you'd probably be better of with 1.14 and above.

I found the problem :)

This the current function in the dhcp_native_ms_main

    def del_record subnet, record
      validate_subnet subnet
      validate_record record
      # TODO: Refactor this into the base class
      raise InvalidRecord, "#{record} is static - unable to delete" unless record.deleteable?

      mac = record.mac.gsub(/:/,"")
      msg = "Removed DHCP reservation for #{record.name} => #{record.ip} - #{record.mac}" 
      cmd = "scope #{subnet.network} delete reservedip #{record.ip} #{mac}" 

      exec_result = execute(cmd, msg)
    end

It supposed to be like this:

    def del_record subnet, record
      validate_subnet subnet
      validate_record record
      # TODO: Refactor this into the base class
      raise InvalidRecord, "#{record} is static - unable to delete" unless record.deleteable?

      mac = record.mac.gsub(/:/,"")
      msg = "Removed DHCP reservation for #{record.name} => #{record.ip} - #{record.mac}" 
      cmd = "scope #{subnet.network} delete reservedip #{record.ip} #{mac}" 

      exec_result = execute(cmd, msg)
      nil
    end

I want to push the fix, should I open a PR to the 1.13-stable branch?

#12 Updated by The Foreman Bot over 4 years ago

  • Status changed from New to Ready For Testing
  • Pull request https://github.com/theforeman/smart-proxy/pull/484 added

#13 Updated by Alex Brodov over 4 years ago

  • Assignee set to Alex Brodov

#14 Updated by Dmitri Dolguikh over 4 years ago

  • Priority changed from High to Normal

#15 Updated by Alex Brodov over 4 years ago

This is one is covered by http://projects.theforeman.org/issues/17847.
The fixes are in place, here's the PR: https://github.com/theforeman/smart-proxy/pull/488. Please review it, and let's merge it to 1.13 branch

#16 Updated by Dominic Cleal over 4 years ago

  • Status changed from Ready For Testing to Closed
  • Legacy Backlogs Release (now unused) set to 213

#17 Updated by Dominic Cleal over 4 years ago

  • Has duplicate Bug #18074: "Failed to destroy the record" error while deleting host added

Also available in: Atom PDF