Project

General

Profile

Actions
Copy link

Bug #11931

closed

MS native DHCP: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry when recycling / removing a dhcp reservation

Added by Daniel Helgenberger about 9 years ago. Updated about 9 years ago.

Status:
Rejected
Priority:
Normal
Assignee:
-
Category:
DHCP
Target version:
-
Difficulty:
Triaged:
Bugzilla link:
Pull request:
Fixed in Releases:
Found in Releases:
Foreman - 1.8.1
Red Hat JIRA:

Description

Description:

Running foreman smart proxy with native_ms, smart-proxy fails to remove the existing dhcp reservation entry; thus failing the host creation. The entry needs to be removed manually.

Steps:

  1. Setup smart proxy on windows host running DHCP with native_ms provider
  2. Add a host, observe dhcp reservation creation
  3. Cancel build
  4. Start build again

Actual result:

ProxyAPI::ProxyException: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::BadRequest]: 400 Bad Request)

Versions

Foreman 1.9.1, Smart Proxy 1.9.1; though I have the issue since I started out with foreman (1.8.1)

Additional information

I have the log set to debug, though all I see in my log are the requests by foremen. I build the netsh command manually from what it should look like from the source and it runs perfectly fine (deleting the record). Most likely unrelated, but strangely smart-proxy logs the following line at startup:

I, [2015-09-23T11:17:21.373438 #3336]  INFO -- : 'dhcp' settings were initialized with default values: :dhcp_omapi_port: 7911, :dhcp_provider: isc

Nevertheless, native_ms seems to be used correctly.
It is easy for me to debug this further at my part right now; and will be happy to help out.

settings.yaml

:log_file: C:\TheForeman\smart-proxy\proxy.log
:log_level: DEBUG

smart proxy settings:

---
:enabled: true
:dhcp_vendor: native_ms

Smart Proxy log (example)

fdff:dd77:2c2c:1110::15 - - [23/Sep/2015 00:07:40] "GET /features HTTP/1.1" 200 14 0.0009
fdff:dd77:2c2c:1110::15 - - [23/Sep/2015 00:07:45] "GET /dhcp/10.11.11.0/10.11.11.51 HTTP/1.1" 404 39 1.0634
fdff:dd77:2c2c:1110::15 - - [23/Sep/2015 00:07:46] "GET /dhcp/10.11.11.0/00:1a:4a:c1:82:06 HTTP/1.1" 200 173 0.7587
fdff:dd77:2c2c:1110::15 - - [23/Sep/2015 00:07:46] "DELETE /dhcp/10.11.11.0/00:1a:4a:c1:82:06 HTTP/1.1" 404 45 0.2734
fdff:dd77:2c2c:1110::15 - - [23/Sep/2015 00:07:48] "POST /dhcp/10.11.11.0 HTTP/1.1" 200 - 1.3711

Production log (example)

2015-09-21 14:06:14 [app] [I] Create DHCP reservation for fm-windepl.corp.com-00:1a:4a:c1:82:06/10.11.11.51
2015-09-21 14:06:16 [app] [W] Create DHCP Settings for fm-windepl.corp.com task failed with the following error: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::BadRequest]: 400 Bad Request) for proxy https://dc01.corp.com:8443/dhcp
 | ProxyAPI::ProxyException: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::BadRequest]: 400 Bad Request) for proxy https://dc01.corp.com:8443/dhcp
 | /usr/share/foreman/lib/proxy_api/dhcp.rb:66:in `rescue in set'
 | /usr/share/foreman/lib/proxy_api/dhcp.rb:62:in `set'
 | /usr/share/foreman/lib/net/dhcp/record.rb:29:in `create'
 | /usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:25:in `set_dhcp'
 | /usr/share/foreman/app/models/concerns/orchestration.rb:152:in `execute'
 | /usr/share/foreman/app/models/concerns/orchestration.rb:97:in `block in process'
 | /usr/share/foreman/app/models/concerns/orchestration.rb:89:in `each'
 | /usr/share/foreman/app/models/concerns/orchestration.rb:89:in `process'
 | /usr/share/foreman/app/models/concerns/orchestration.rb:19:in `on_save'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:660:in `_run__983570689565321651__save__3350210477228793458__callbacks'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `__run_callback'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:385:in `_run_save_callbacks'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:81:in `run_callbacks'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/callbacks.rb:264:in `create_or_update'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/persistence.rb:84:in `save'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/validations.rb:50:in `save'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/attribute_methods/dirty.rb:22:in `save'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:241:in `block (2 levels) in save'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:295:in `block in with_transaction_returning_status'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract/database_statements.rb:192:in `transaction'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:208:in `transaction'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:293:in `with_transaction_returning_status'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:241:in `block in save'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:252:in `rollback_active_record_state!'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:240:in `save'
 | /usr/share/foreman/app/models/concerns/foreman/sti.rb:29:in `save_with_type'
 | /usr/share/foreman/app/models/host/managed.rb:472:in `setBuild'
 | /usr/share/foreman/app/controllers/hosts_controller.rb:201:in `setBuild'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/base.rb:167:in `process_action'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/rendering.rb:10:in `process_action'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/callbacks.rb:18:in `block in process_action'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:649:in `block (4 levels) in _run__1457838564463358174__process_action__2078018436191374942__callbacks'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:215:in `block in _conditional_callback_around_7865'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:326:in `around'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:310:in `_callback_around_2439'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_7865'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:626:in `block (3 levels) in _run__1457838564463358174__process_action__2078018436191374942__callbacks'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:215:in `block in _conditional_callback_around_7864'
 | /usr/share/foreman/app/controllers/concerns/application_shared.rb:13:in `set_timezone'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_7864'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:625:in `block (2 levels) in _run__1457838564463358174__process_action__2078018436191374942__callbacks'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:215:in `block in _conditional_callback_around_7863'
 | /usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_7863'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:448:in `block in _run__1457838564463358174__process_action__2078018436191374942__callbacks'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:215:in `block in _conditional_callback_around_7862'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:326:in `around'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:310:in `_callback_around_13'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_7862'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:414:in `_run__1457838564463358174__process_action__2078018436191374942__callbacks'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `__run_callback'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:385:in `_run_process_action_callbacks'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:81:in `run_callbacks'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/callbacks.rb:17:in `process_action'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/rescue.rb:29:in `process_action'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/instrumentation.rb:30:in `block in process_action'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/notifications.rb:123:in `block in instrument'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
( ... )
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/notifications.rb:123:in `block in instrument'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/notifications.rb:123:in `instrument'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/instrumentation.rb:29:in `process_action'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/params_wrapper.rb:207:in `process_action'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/base.rb:121:in `process'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/rendering.rb:45:in `process'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal.rb:203:in `dispatch'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal.rb:246:in `block in action'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:73:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:73:in `dispatch'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:36:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/journey-1.0.4/lib/journey/router.rb:68:in `block in call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/journey-1.0.4/lib/journey/router.rb:56:in `each'
 | /opt/rh/ruby193/root/usr/share/gems/gems/journey-1.0.4/lib/journey/router.rb:56:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:600:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/apipie-rails-0.2.6/lib/apipie/extractor/recorder.rb:97:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/static.rb:62:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/apipie-rails-0.2.6/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/etag.rb:23:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/conditionalget.rb:35:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/head.rb:14:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/params_parser.rb:21:in `call'
 | /usr/share/foreman/lib/middleware/catch_json_parse_errors.rb:9:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/flash.rb:242:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:205:in `context'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:200:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/cookies.rb:339:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/query_cache.rb:64:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract/connection_pool.rb:473:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `_run__3803644768944755927__call__3350210477228793458__callbacks'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `__run_callback'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:385:in `_run_call_callbacks'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:81:in `run_callbacks'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/rack/logger.rb:26:in `call_app'
 | /opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/rack/logger.rb:16:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/request_id.rb:22:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/methodoverride.rb:21:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/runtime.rb:17:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/cache/strategy/local_cache.rb:72:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/lock.rb:15:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/static.rb:62:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:136:in `forward'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:143:in `pass'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:155:in `invalidate'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:71:in `call!'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:51:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/engine.rb:479:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/application.rb:223:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/railtie/configurable.rb:30:in `method_missing'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/builder.rb:134:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/urlmap.rb:64:in `block in call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/urlmap.rb:49:in `each'
 | /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/urlmap.rb:49:in `call'
 | /usr/share/gems/gems/passenger-4.0.18/lib/phusion_passenger/rack/thread_handler_extension.rb:77:in `process_request'
 | /usr/share/gems/gems/passenger-4.0.18/lib/phusion_passenger/request_handler/thread_handler.rb:140:in `accept_and_process_next_request'
 | /usr/share/gems/gems/passenger-4.0.18/lib/phusion_passenger/request_handler/thread_handler.rb:108:in `main_loop'
 | /usr/share/gems/gems/passenger-4.0.18/lib/phusion_passenger/request_handler.rb:441:in `block (3 levels) in start_threads'
 | /opt/rh/ruby193/root/usr/share/gems/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `call'
 | /opt/rh/ruby193/root/usr/share/gems/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'
2015-09-21 14:06:17 [app] [I] Failed to save: Create DHCP Settings for fm-windepl.corp.com task failed with the following error: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::BadRequest]: 400 Bad Request) for proxy https://dc01.corp.com:8443/dhcp, Failed to perform rollback on Remove DHCP Settings for fm-windepl.corp.com - ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::BadRequest]: 400 Bad Request) for proxy https://dc01.corp.com:8443/dhcp
Actions
Copy link
 #1

Updated by Dominic Cleal about 9 years ago

Daniel Helgenberger wrote:

I have the log set to debug, though all I see in my log are the requests by foremen. I build the netsh command manually from what it should look like from the source and it runs perfectly fine (deleting the record). Most likely unrelated, but strangely smart-proxy logs the following line at startup:
[...]
Nevertheless, native_ms seems to be used correctly.

The :dhcp_provider: isc line is odd, but I think it's just a harmless bug. The setting's initialised internally but not used.

Smart Proxy log (example)

The smart proxy log doesn't contain any useful information here - in fact, it's showing a 200 response code when the production (Foreman) log is clearly showing the proxy is giving a 400 response. The dates also don't match.

Can you get matching logs? The proxy log should at least show the same 4xx response code if there's a problem.

There should also be many more lines at INFO or DEBUG level showing the netsh commands etc.

Actions
Copy link
 #2

Updated by Daniel Helgenberger about 9 years ago

Sorry that they are not matching, I try to generate a matching log asap. Anyway:

fdff:dd77:2c2c:1110::15 - - [23/Sep/2015 00:07:46] "DELETE /dhcp/10.11.11.0/00:1a:4a:c1:82:06 HTTP/1.1" 404 45 0.2734

is 404 and not 200 ...

I also think :DEBUG is correctly set, but nevertheless I only got INFO
I'll try to run smartproxy in foreground and see if I get any more output.

Actions
Copy link
 #3

Updated by Anonymous about 9 years ago

Check smart-proxy main config file, it should have log_level property set to 'DEBUG'.

Actions
Copy link
 #4

Updated by Dominic Cleal about 9 years ago

Yeah, the DELETE 404 line might be quite acceptable if Foreman requested the deletion of a record that wasn't initially created. It's a POST 400 that you'd expect in the logs to correspond to the Foreman error you're reporting.

Actions
Copy link
 #5

Updated by Daniel Helgenberger about 9 years ago

Ok, DEBUG and console seems to be better. I think I might have found the issue.
Below the long output from one request.

Bottom line, netsh does not allow do 'add' an existing MAC again, it needs to be removed and then added again. I cannot see removes here? (sorry for line breaks cat column 140, stupid windows console)

[2015-09-23 12:35:08] INFO  WEBrick::HTTPServer#start: pid=5848 port=8443
D, [2015-09-23T12:35:19.384866 #5848] DEBUG -- : verifying remote client fdff:dd77:2c2c:1110::15 against trusted_hosts ["foreman.int.m-box.d
e"]
D, [2015-09-23T12:35:19.397610 #5848] DEBUG -- : Loading subnets for 127.0.0.1
D, [2015-09-23T12:35:19.409287 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 show scope
I, [2015-09-23T12:35:19.476662 #5848]  INFO -- : Enumerated the scopes on 127.0.0.1
D, [2015-09-23T12:35:19.477607 #5848] DEBUG -- : Added 10.11.2.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:19.477607 #5848] DEBUG -- : Added 10.11.3.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:19.478658 #5848] DEBUG -- : Added 10.11.10.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:19.479619 #5848] DEBUG -- : Added 10.11.11.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:19.479619 #5848] DEBUG -- : Added 172.30.0.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:19.482527 #5848] DEBUG -- : Loading subnet data for 10.11.2.0/255.255.255.0
D, [2015-09-23T12:35:19.483529 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.2.0 show reservedip
I, [2015-09-23T12:35:19.565462 #5848]  INFO -- : Enumerated hosts on 10.11.2.0
D, [2015-09-23T12:35:19.565462 #5848] DEBUG -- : Lazy loaded 10.11.2.0/255.255.255.0 records
D, [2015-09-23T12:35:19.566427 #5848] DEBUG -- : Loading subnet data for 10.11.3.0/255.255.255.0
D, [2015-09-23T12:35:19.566427 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.3.0 show reservedip
I, [2015-09-23T12:35:19.643908 #5848]  INFO -- : Enumerated hosts on 10.11.3.0
D, [2015-09-23T12:35:19.644261 #5848] DEBUG -- : Lazy loaded 10.11.3.0/255.255.255.0 records
D, [2015-09-23T12:35:19.644925 #5848] DEBUG -- : Loading subnet data for 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:19.645677 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 show reservedip
I, [2015-09-23T12:35:19.714978 #5848]  INFO -- : Enumerated hosts on 10.11.10.0
D, [2015-09-23T12:35:19.714978 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.20
I, [2015-09-23T12:35:19.783232 #5848]  INFO -- : Queried 10.11.10.20 options
D, [2015-09-23T12:35:19.784302 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:19.784302 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:19.784302 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:19.785281 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"repos.corp.com"}
D, [2015-09-23T12:35:19.785281 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.20", :mac=>"00:1a:4a:c1:82:02", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"repos.corp.com"}
D, [2015-09-23T12:35:19.785281 #5848] DEBUG -- : Added 10.11.10.20 / 00:1a:4a:c1:82:02 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:19.786276 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.21
I, [2015-09-23T12:35:19.856480 #5848]  INFO -- : Queried 10.11.10.21 options
D, [2015-09-23T12:35:19.857474 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:19.857474 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:19.858612 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:19.859513 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-deploy.int.m-box
.de"}
D, [2015-09-23T12:35:19.859513 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.21", :mac=>"00:1a:4a:c1:82:03", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-deploy.corp.com"}
D, [2015-09-23T12:35:19.860497 #5848] DEBUG -- : Added 10.11.10.21 / 00:1a:4a:c1:82:03 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:19.861461 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.200
I, [2015-09-23T12:35:19.951277 #5848]  INFO -- : Queried 10.11.10.200 options
D, [2015-09-23T12:35:19.952167 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:19.952167 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:19.953217 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:19.953217 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"testlab.corp.com" 
}
D, [2015-09-23T12:35:19.953217 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.200", :mac=>"00:1a:4a:c1:82:04", :nextSe
rver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"testlab.corp.com"}
D, [2015-09-23T12:35:19.954204 #5848] DEBUG -- : Added 10.11.10.200 / 00:1a:4a:c1:82:04 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:19.955250 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.22
I, [2015-09-23T12:35:20.045023 #5848]  INFO -- : Queried 10.11.10.22 options
D, [2015-09-23T12:35:20.045023 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:20.046035 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:20.047054 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:20.047054 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"license01.int.m-box.d
e"}
D, [2015-09-23T12:35:20.048004 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.22", :mac=>"de:ad:04:fa:de:02", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"license01.corp.com"}
D, [2015-09-23T12:35:20.049877 #5848] DEBUG -- : Added 10.11.10.22 / de:ad:04:fa:de:02 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:20.051827 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.23
I, [2015-09-23T12:35:20.121221 #5848]  INFO -- : Queried 10.11.10.23 options
D, [2015-09-23T12:35:20.124129 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:20.126010 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:20.128055 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:20.130973 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-host.int.m-box.d
e"}
D, [2015-09-23T12:35:20.133904 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.23", :mac=>"00:1a:4a:c1:82:06", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-host.corp.com"}
D, [2015-09-23T12:35:20.137708 #5848] DEBUG -- : Added 10.11.10.23 / 00:1a:4a:c1:82:06 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:20.139707 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.16
I, [2015-09-23T12:35:20.214019 #5848]  INFO -- : Queried 10.11.10.16 options
D, [2015-09-23T12:35:20.216056 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:20.218900 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:20.231065 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:20.233483 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"puppetdb.corp.com
"}
D, [2015-09-23T12:35:20.236351 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.16", :mac=>"00:1a:4a:c1:82:08", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"puppetdb.corp.com"}
D, [2015-09-23T12:35:20.244299 #5848] DEBUG -- : Added 10.11.10.16 / 00:1a:4a:c1:82:08 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:20.246276 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.17
I, [2015-09-23T12:35:20.319428 #5848]  INFO -- : Queried 10.11.10.17 options
D, [2015-09-23T12:35:20.321377 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:20.323352 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:20.325265 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:20.327277 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"windeploy.int.m-box.d
e"}
D, [2015-09-23T12:35:20.330227 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.17", :mac=>"00:1a:4a:c1:82:09", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"windeploy.corp.com"}
D, [2015-09-23T12:35:20.333082 #5848] DEBUG -- : Added 10.11.10.17 / 00:1a:4a:c1:82:09 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:20.335093 #5848] DEBUG -- : Lazy loaded 10.11.10.0/255.255.255.0 records
D, [2015-09-23T12:35:20.337011 #5848] DEBUG -- : Loading subnet data for 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:20.339003 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 show reservedip
I, [2015-09-23T12:35:20.407263 #5848]  INFO -- : Enumerated hosts on 10.11.11.0
D, [2015-09-23T12:35:20.409266 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 Show ReservedOptionValue 10.11.11.14
I, [2015-09-23T12:35:20.480537 #5848]  INFO -- : Queried 10.11.11.14 options
D, [2015-09-23T12:35:20.482523 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:20.483503 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:20.485412 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:20.487423 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"p500b.corp.com"}
D, [2015-09-23T12:35:20.489376 #5848] DEBUG -- : {:subnet=>10.11.11.0/255.255.255.0, :ip=>"10.11.11.14", :mac=>"6c:0b:84:0c:42:6b", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"p500b.corp.com"}
D, [2015-09-23T12:35:20.492213 #5848] DEBUG -- : Added 10.11.11.14 / 6c:0b:84:0c:42:6b to 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:20.495242 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 Show ReservedOptionValue 10.11.11.15
I, [2015-09-23T12:35:20.573313 #5848]  INFO -- : Queried 10.11.11.15 options
D, [2015-09-23T12:35:20.575338 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:20.577247 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:20.579236 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:20.581101 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"wstest01.corp.com
"}
D, [2015-09-23T12:35:20.584070 #5848] DEBUG -- : {:subnet=>10.11.11.0/255.255.255.0, :ip=>"10.11.11.15", :mac=>"00:1a:4a:c1:82:05", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"wstest01.corp.com"}
D, [2015-09-23T12:35:20.587007 #5848] DEBUG -- : Added 10.11.11.15 / 00:1a:4a:c1:82:05 to 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:20.588920 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 Show ReservedOptionValue 10.11.11.51
I, [2015-09-23T12:35:20.662200 #5848]  INFO -- : Queried 10.11.11.51 options
D, [2015-09-23T12:35:20.664155 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:20.666171 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:20.668004 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:20.670010 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"fm-windepl.int.m-box.
de"}
D, [2015-09-23T12:35:20.671915 #5848] DEBUG -- : {:subnet=>10.11.11.0/255.255.255.0, :ip=>"10.11.11.51", :mac=>"00:1a:4a:c1:82:06", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"fm-windepl.corp.com"}
D, [2015-09-23T12:35:20.679736 #5848] DEBUG -- : Added 10.11.11.51 / 00:1a:4a:c1:82:06 to 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:20.681687 #5848] DEBUG -- : Lazy loaded 10.11.11.0/255.255.255.0 records
fdff:dd77:2c2c:1110::15 - - [23/Sep/2015 12:35:20] "GET /dhcp/10.11.11.0/10.11.11.51 HTTP/1.1" 200 174 1.3105
foreman.corp.com - - [23/Sep/2015:12:35:19 W. Europe Daylight Time] "GET /dhcp/10.11.11.0/10.11.11.51 HTTP/1.1" 200 174
- -> /dhcp/10.11.11.0/10.11.11.51
D, [2015-09-23T12:35:20.823346 #5848] DEBUG -- : verifying remote client fdff:dd77:2c2c:1110::15 against trusted_hosts ["foreman.int.m-box.d
e"]
D, [2015-09-23T12:35:20.827229 #5848] DEBUG -- : Loading subnets for 127.0.0.1
D, [2015-09-23T12:35:20.829145 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 show scope
I, [2015-09-23T12:35:20.905490 #5848]  INFO -- : Enumerated the scopes on 127.0.0.1
D, [2015-09-23T12:35:20.907368 #5848] DEBUG -- : Added 10.11.2.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:20.909292 #5848] DEBUG -- : Added 10.11.3.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:20.913115 #5848] DEBUG -- : Added 10.11.10.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:20.916132 #5848] DEBUG -- : Added 10.11.11.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:20.920032 #5848] DEBUG -- : Added 172.30.0.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:20.921917 #5848] DEBUG -- : Loading subnet data for 10.11.2.0/255.255.255.0
D, [2015-09-23T12:35:20.923864 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.2.0 show reservedip
I, [2015-09-23T12:35:21.004954 #5848]  INFO -- : Enumerated hosts on 10.11.2.0
D, [2015-09-23T12:35:21.005885 #5848] DEBUG -- : Lazy loaded 10.11.2.0/255.255.255.0 records
D, [2015-09-23T12:35:21.008886 #5848] DEBUG -- : Loading subnet data for 10.11.3.0/255.255.255.0
D, [2015-09-23T12:35:21.010838 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.3.0 show reservedip
I, [2015-09-23T12:35:21.084105 #5848]  INFO -- : Enumerated hosts on 10.11.3.0
D, [2015-09-23T12:35:21.086006 #5848] DEBUG -- : Lazy loaded 10.11.3.0/255.255.255.0 records
D, [2015-09-23T12:35:21.088885 #5848] DEBUG -- : Loading subnet data for 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:21.091887 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 show reservedip
I, [2015-09-23T12:35:21.166084 #5848]  INFO -- : Enumerated hosts on 10.11.10.0
D, [2015-09-23T12:35:21.168064 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.20
I, [2015-09-23T12:35:21.240268 #5848]  INFO -- : Queried 10.11.10.20 options
D, [2015-09-23T12:35:21.242315 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:21.244229 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:21.245237 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:21.248163 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"repos.corp.com"}
D, [2015-09-23T12:35:21.249139 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.20", :mac=>"00:1a:4a:c1:82:02", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"repos.corp.com"}
D, [2015-09-23T12:35:21.253022 #5848] DEBUG -- : Added 10.11.10.20 / 00:1a:4a:c1:82:02 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:21.254946 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.21
I, [2015-09-23T12:35:21.327180 #5848]  INFO -- : Queried 10.11.10.21 options
D, [2015-09-23T12:35:21.329237 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:21.331231 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:21.333093 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:21.335130 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-deploy.int.m-box
.de"}
D, [2015-09-23T12:35:21.342850 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.21", :mac=>"00:1a:4a:c1:82:03", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-deploy.corp.com"}
D, [2015-09-23T12:35:21.347748 #5848] DEBUG -- : Added 10.11.10.21 / 00:1a:4a:c1:82:03 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:21.350692 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.200
I, [2015-09-23T12:35:21.425902 #5848]  INFO -- : Queried 10.11.10.200 options
D, [2015-09-23T12:35:21.427839 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:21.429776 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:21.431752 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:21.434696 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"testlab.corp.com" 
}
D, [2015-09-23T12:35:21.437624 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.200", :mac=>"00:1a:4a:c1:82:04", :nextSe
rver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"testlab.corp.com"}
D, [2015-09-23T12:35:21.440564 #5848] DEBUG -- : Added 10.11.10.200 / 00:1a:4a:c1:82:04 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:21.443448 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.22
I, [2015-09-23T12:35:21.512803 #5848]  INFO -- : Queried 10.11.10.22 options
D, [2015-09-23T12:35:21.514759 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:21.516766 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:21.518654 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:21.520617 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"license01.int.m-box.d
e"}
D, [2015-09-23T12:35:21.525532 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.22", :mac=>"de:ad:04:fa:de:02", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"license01.corp.com"}
D, [2015-09-23T12:35:21.532341 #5848] DEBUG -- : Added 10.11.10.22 / de:ad:04:fa:de:02 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:21.535251 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.23
I, [2015-09-23T12:35:21.616288 #5848]  INFO -- : Queried 10.11.10.23 options
D, [2015-09-23T12:35:21.618255 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:21.620352 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:21.622160 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:21.624122 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-host.int.m-box.d
e"}
D, [2015-09-23T12:35:21.627985 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.23", :mac=>"00:1a:4a:c1:82:06", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-host.corp.com"}
D, [2015-09-23T12:35:21.630995 #5848] DEBUG -- : Added 10.11.10.23 / 00:1a:4a:c1:82:06 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:21.633876 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.16
I, [2015-09-23T12:35:21.704228 #5848]  INFO -- : Queried 10.11.10.16 options
D, [2015-09-23T12:35:21.706095 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:21.708139 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:21.710020 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:21.712003 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"puppetdb.corp.com
"}
D, [2015-09-23T12:35:21.714978 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.16", :mac=>"00:1a:4a:c1:82:08", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"puppetdb.corp.com"}
D, [2015-09-23T12:35:21.718791 #5848] DEBUG -- : Added 10.11.10.16 / 00:1a:4a:c1:82:08 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:21.721774 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.17
I, [2015-09-23T12:35:21.790106 #5848]  INFO -- : Queried 10.11.10.17 options
D, [2015-09-23T12:35:21.792112 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:21.793999 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:21.797914 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:21.798912 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"windeploy.int.m-box.d
e"}
D, [2015-09-23T12:35:21.802918 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.17", :mac=>"00:1a:4a:c1:82:09", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"windeploy.corp.com"}
D, [2015-09-23T12:35:21.806799 #5848] DEBUG -- : Added 10.11.10.17 / 00:1a:4a:c1:82:09 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:21.809742 #5848] DEBUG -- : Lazy loaded 10.11.10.0/255.255.255.0 records
fdff:dd77:2c2c:1110::15 - - [23/Sep/2015 12:35:21] "GET /dhcp/10.11.11.0/00:1a:4a:c1:82:06 HTTP/1.1" 200 173 0.9892
foreman.corp.com - - [23/Sep/2015:12:35:20 W. Europe Daylight Time] "GET /dhcp/10.11.11.0/00:1a:4a:c1:82:06 HTTP/1.1" 200 173
- -> /dhcp/10.11.11.0/00:1a:4a:c1:82:06
D, [2015-09-23T12:35:22.061741 #5848] DEBUG -- : verifying remote client fdff:dd77:2c2c:1110::15 against trusted_hosts ["foreman.int.m-box.d
e"]
D, [2015-09-23T12:35:22.064604 #5848] DEBUG -- : Loading subnets for 127.0.0.1
D, [2015-09-23T12:35:22.066542 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 show scope
I, [2015-09-23T12:35:22.131964 #5848]  INFO -- : Enumerated the scopes on 127.0.0.1
D, [2015-09-23T12:35:22.133915 #5848] DEBUG -- : Added 10.11.2.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:22.135874 #5848] DEBUG -- : Added 10.11.3.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:22.137717 #5848] DEBUG -- : Added 10.11.10.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:22.139700 #5848] DEBUG -- : Added 10.11.11.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:22.141730 #5848] DEBUG -- : Added 172.30.0.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:22.143735 #5848] DEBUG -- : Loading subnet data for 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:22.145632 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 show reservedip
I, [2015-09-23T12:35:22.214999 #5848]  INFO -- : Enumerated hosts on 10.11.11.0
D, [2015-09-23T12:35:22.215974 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 Show ReservedOptionValue 10.11.11.14
I, [2015-09-23T12:35:22.283365 #5848]  INFO -- : Queried 10.11.11.14 options
D, [2015-09-23T12:35:22.285248 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:22.287228 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:22.289154 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:22.292098 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"p500b.corp.com"}
D, [2015-09-23T12:35:22.294095 #5848] DEBUG -- : {:subnet=>10.11.11.0/255.255.255.0, :ip=>"10.11.11.14", :mac=>"6c:0b:84:0c:42:6b", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"p500b.corp.com"}
D, [2015-09-23T12:35:22.300908 #5848] DEBUG -- : Added 10.11.11.14 / 6c:0b:84:0c:42:6b to 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:22.302790 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 Show ReservedOptionValue 10.11.11.15
I, [2015-09-23T12:35:22.375085 #5848]  INFO -- : Queried 10.11.11.15 options
D, [2015-09-23T12:35:22.377052 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:22.379116 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:22.381929 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:22.383875 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"wstest01.corp.com
"}
D, [2015-09-23T12:35:22.386733 #5848] DEBUG -- : {:subnet=>10.11.11.0/255.255.255.0, :ip=>"10.11.11.15", :mac=>"00:1a:4a:c1:82:05", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"wstest01.corp.com"}
D, [2015-09-23T12:35:22.390815 #5848] DEBUG -- : Added 10.11.11.15 / 00:1a:4a:c1:82:05 to 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:22.397602 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 Show ReservedOptionValue 10.11.11.51
I, [2015-09-23T12:35:22.481597 #5848]  INFO -- : Queried 10.11.11.51 options
D, [2015-09-23T12:35:22.483430 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:22.485497 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:22.488390 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:22.490370 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"fm-windepl.int.m-box.
de"}
D, [2015-09-23T12:35:22.493282 #5848] DEBUG -- : {:subnet=>10.11.11.0/255.255.255.0, :ip=>"10.11.11.51", :mac=>"00:1a:4a:c1:82:06", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"fm-windepl.corp.com"}
D, [2015-09-23T12:35:22.497121 #5848] DEBUG -- : Added 10.11.11.51 / 00:1a:4a:c1:82:06 to 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:22.499198 #5848] DEBUG -- : Lazy loaded 10.11.11.0/255.255.255.0 records
E, [2015-09-23T12:35:22.502117 #5848] ERROR -- : Record 10.11.11.0/00:1a:4a:c1:82:06 not found
fdff:dd77:2c2c:1110::15 - - [23/Sep/2015 12:35:22] "DELETE /dhcp/10.11.11.0/00:1a:4a:c1:82:06 HTTP/1.1" 404 45 0.4423
foreman.corp.com - - [23/Sep/2015:12:35:22 W. Europe Daylight Time] "DELETE /dhcp/10.11.11.0/00:1a:4a:c1:82:06 HTTP/1.1" 404 45
- -> /dhcp/10.11.11.0/00:1a:4a:c1:82:06
D, [2015-09-23T12:35:22.668991 #5848] DEBUG -- : verifying remote client fdff:dd77:2c2c:1110::15 against trusted_hosts ["foreman.int.m-box.d
e"]
D, [2015-09-23T12:35:22.672933 #5848] DEBUG -- : Loading subnets for 127.0.0.1
D, [2015-09-23T12:35:22.675937 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 show scope
I, [2015-09-23T12:35:22.766753 #5848]  INFO -- : Enumerated the scopes on 127.0.0.1
D, [2015-09-23T12:35:22.768647 #5848] DEBUG -- : Added 10.11.2.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:22.771603 #5848] DEBUG -- : Added 10.11.3.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:22.773485 #5848] DEBUG -- : Added 10.11.10.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:22.775546 #5848] DEBUG -- : Added 10.11.11.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:22.777436 #5848] DEBUG -- : Added 172.30.0.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:22.780347 #5848] DEBUG -- : Loading subnet data for 10.11.2.0/255.255.255.0
D, [2015-09-23T12:35:22.782319 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.2.0 show reservedip
I, [2015-09-23T12:35:22.869343 #5848]  INFO -- : Enumerated hosts on 10.11.2.0
D, [2015-09-23T12:35:22.872208 #5848] DEBUG -- : Lazy loaded 10.11.2.0/255.255.255.0 records
D, [2015-09-23T12:35:22.874154 #5848] DEBUG -- : Loading subnet data for 10.11.3.0/255.255.255.0
D, [2015-09-23T12:35:22.876067 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.3.0 show reservedip
I, [2015-09-23T12:35:22.966846 #5848]  INFO -- : Enumerated hosts on 10.11.3.0
D, [2015-09-23T12:35:22.968958 #5848] DEBUG -- : Lazy loaded 10.11.3.0/255.255.255.0 records
D, [2015-09-23T12:35:22.971769 #5848] DEBUG -- : Loading subnet data for 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:22.973694 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 show reservedip
I, [2015-09-23T12:35:23.050905 #5848]  INFO -- : Enumerated hosts on 10.11.10.0
D, [2015-09-23T12:35:23.054735 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.20
I, [2015-09-23T12:35:23.126064 #5848]  INFO -- : Queried 10.11.10.20 options
D, [2015-09-23T12:35:23.128055 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:23.130087 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:23.131953 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:23.133880 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"repos.corp.com"}
D, [2015-09-23T12:35:23.136793 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.20", :mac=>"00:1a:4a:c1:82:02", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"repos.corp.com"}
D, [2015-09-23T12:35:23.139695 #5848] DEBUG -- : Added 10.11.10.20 / 00:1a:4a:c1:82:02 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:23.141675 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.21
I, [2015-09-23T12:35:23.210042 #5848]  INFO -- : Queried 10.11.10.21 options
D, [2015-09-23T12:35:23.213049 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:23.214924 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:23.215935 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:23.217862 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-deploy.int.m-box
.de"}
D, [2015-09-23T12:35:23.220835 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.21", :mac=>"00:1a:4a:c1:82:03", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-deploy.corp.com"}
D, [2015-09-23T12:35:23.224816 #5848] DEBUG -- : Added 10.11.10.21 / 00:1a:4a:c1:82:03 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:23.226754 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.200
I, [2015-09-23T12:35:23.292039 #5848]  INFO -- : Queried 10.11.10.200 options
D, [2015-09-23T12:35:23.293970 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:23.296012 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:23.298041 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:23.299867 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"testlab.corp.com" 
}
D, [2015-09-23T12:35:23.300885 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.200", :mac=>"00:1a:4a:c1:82:04", :nextSe
rver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"testlab.corp.com"}
D, [2015-09-23T12:35:23.303412 #5848] DEBUG -- : Added 10.11.10.200 / 00:1a:4a:c1:82:04 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:23.314566 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.22
I, [2015-09-23T12:35:23.392670 #5848]  INFO -- : Queried 10.11.10.22 options
D, [2015-09-23T12:35:23.394568 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:23.396564 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:23.399444 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:23.401492 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"license01.int.m-box.d
e"}
D, [2015-09-23T12:35:23.404323 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.22", :mac=>"de:ad:04:fa:de:02", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"license01.corp.com"}
D, [2015-09-23T12:35:23.418685 #5848] DEBUG -- : Added 10.11.10.22 / de:ad:04:fa:de:02 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:23.421056 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.23
I, [2015-09-23T12:35:23.500169 #5848]  INFO -- : Queried 10.11.10.23 options
D, [2015-09-23T12:35:23.502045 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:23.503015 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:23.505927 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:23.506941 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-host.int.m-box.d
e"}
D, [2015-09-23T12:35:23.521804 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.23", :mac=>"00:1a:4a:c1:82:06", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-host.corp.com"}
D, [2015-09-23T12:35:23.524486 #5848] DEBUG -- : Added 10.11.10.23 / 00:1a:4a:c1:82:06 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:23.527395 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.16
I, [2015-09-23T12:35:23.597710 #5848]  INFO -- : Queried 10.11.10.16 options
D, [2015-09-23T12:35:23.600702 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:23.602697 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:23.605578 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:23.608492 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"puppetdb.corp.com
"}
D, [2015-09-23T12:35:23.612462 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.16", :mac=>"00:1a:4a:c1:82:08", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"puppetdb.corp.com"}
D, [2015-09-23T12:35:23.615383 #5848] DEBUG -- : Added 10.11.10.16 / 00:1a:4a:c1:82:08 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:23.621264 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.17
I, [2015-09-23T12:35:23.695354 #5848]  INFO -- : Queried 10.11.10.17 options
D, [2015-09-23T12:35:23.697291 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:23.713006 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:23.714998 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:23.716913 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"windeploy.int.m-box.d
e"}
D, [2015-09-23T12:35:23.719853 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.17", :mac=>"00:1a:4a:c1:82:09", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"windeploy.corp.com"}
D, [2015-09-23T12:35:23.722775 #5848] DEBUG -- : Added 10.11.10.17 / 00:1a:4a:c1:82:09 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:23.725613 #5848] DEBUG -- : Lazy loaded 10.11.10.0/255.255.255.0 records
D, [2015-09-23T12:35:23.727701 #5848] DEBUG -- : Loading subnet data for 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:23.730545 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 show reservedip
I, [2015-09-23T12:35:23.796902 #5848]  INFO -- : Enumerated hosts on 10.11.11.0
D, [2015-09-23T12:35:23.798902 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 Show ReservedOptionValue 10.11.11.14
I, [2015-09-23T12:35:23.879997 #5848]  INFO -- : Queried 10.11.11.14 options
D, [2015-09-23T12:35:23.881940 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:23.884860 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:23.893615 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:23.907273 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"p500b.corp.com"}
D, [2015-09-23T12:35:23.910191 #5848] DEBUG -- : {:subnet=>10.11.11.0/255.255.255.0, :ip=>"10.11.11.14", :mac=>"6c:0b:84:0c:42:6b", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"p500b.corp.com"}
D, [2015-09-23T12:35:23.913177 #5848] DEBUG -- : Added 10.11.11.14 / 6c:0b:84:0c:42:6b to 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:23.916194 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 Show ReservedOptionValue 10.11.11.15
I, [2015-09-23T12:35:23.995645 #5848]  INFO -- : Queried 10.11.11.15 options
D, [2015-09-23T12:35:23.998122 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:24.001052 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:24.003005 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:24.005003 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"wstest01.corp.com
"}
D, [2015-09-23T12:35:24.007917 #5848] DEBUG -- : {:subnet=>10.11.11.0/255.255.255.0, :ip=>"10.11.11.15", :mac=>"00:1a:4a:c1:82:05", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"wstest01.corp.com"}
D, [2015-09-23T12:35:24.013884 #5848] DEBUG -- : Added 10.11.11.15 / 00:1a:4a:c1:82:05 to 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:24.017079 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 Show ReservedOptionValue 10.11.11.51
I, [2015-09-23T12:35:24.106482 #5848]  INFO -- : Queried 10.11.11.51 options
D, [2015-09-23T12:35:24.108513 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:24.111766 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:24.113394 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:24.114381 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"fm-windepl.int.m-box.
de"}
D, [2015-09-23T12:35:24.118328 #5848] DEBUG -- : {:subnet=>10.11.11.0/255.255.255.0, :ip=>"10.11.11.51", :mac=>"00:1a:4a:c1:82:06", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"fm-windepl.corp.com"}
D, [2015-09-23T12:35:24.121391 #5848] DEBUG -- : Added 10.11.11.51 / 00:1a:4a:c1:82:06 to 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:24.124273 #5848] DEBUG -- : Lazy loaded 10.11.11.0/255.255.255.0 records
D, [2015-09-23T12:35:24.131053 #5848] DEBUG -- : Added fm-windepl.corp.com (10.11.11.51 / 00:1a:4a:c1:82:06) to 10.11.11.0/255.255.255.0

D, [2015-09-23T12:35:24.133966 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 add reservedip 10.11.11.51 001a4ac18206 fm-windepl.corp.com
I, [2015-09-23T12:35:24.212916 #5848]  INFO -- : Vendor class not found
E, [2015-09-23T12:35:24.215925 #5848] ERROR -- : Failed to add DHCP reservation for fm-windepl.corp.com (10.11.11.51 / 00:1a:4a:c1:82:06
)Vendor class not found: ["The specified IP address or hardware address is being used by another client.\n"]
D, [2015-09-23T12:35:24.219814 #5848] DEBUG -- : c:/TheForeman/smart-proxy/modules/dhcp/providers/server/native_ms.rb:215:in `report'
c:/TheForeman/smart-proxy/modules/dhcp/providers/server/native_ms.rb:195:in `execute'
c:/TheForeman/smart-proxy/modules/dhcp/providers/server/native_ms.rb:35:in `addRecord'
c:/TheForeman/smart-proxy/modules/dhcp/dhcp_api.rb:96:in `block in <class:DhcpApi>'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `block in compile!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `[]'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (3 levels) in route!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:993:in `route_eval'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (2 levels) in route!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1014:in `block in process_route'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `catch'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `process_route'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:972:in `block in route!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `each'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `route!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1084:in `block in dispatch!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1081:in `dispatch!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `block in call!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `call!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:894:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/methodoverride.rb:21:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/commonlogger.rb:33:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:218:in `call'
c:/TheForeman/smart-proxy/lib/proxy/log.rb:35:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/nulllogger.rb:9:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/head.rb:11:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/show_exceptions.rb:21:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:181:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:2021:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `block in call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1795:in `synchronize'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/urlmap.rb:65:in `block in call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `each'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/handler/webrick.rb:60:in `service'
C:/Ruby200-x64/lib/ruby/2.0.0/webrick/httpserver.rb:138:in `service'
C:/Ruby200-x64/lib/ruby/2.0.0/webrick/httpserver.rb:94:in `run'
C:/Ruby200-x64/lib/ruby/2.0.0/webrick/server.rb:295:in `block in start_thread'
fdff:dd77:2c2c:1110::15 - - [23/Sep/2015 12:35:24] "POST /dhcp/10.11.11.0 HTTP/1.1" 400 199 1.6482
foreman.corp.com - - [23/Sep/2015:12:35:22 W. Europe Daylight Time] "POST /dhcp/10.11.11.0 HTTP/1.1" 400 199
- -> /dhcp/10.11.11.0
D, [2015-09-23T12:35:24.485440 #5848] DEBUG -- : verifying remote client fdff:dd77:2c2c:1110::15 against trusted_hosts ["foreman.int.m-box.d
e"]
D, [2015-09-23T12:35:24.489295 #5848] DEBUG -- : Loading subnets for 127.0.0.1
D, [2015-09-23T12:35:24.491306 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 show scope
I, [2015-09-23T12:35:24.562663 #5848]  INFO -- : Enumerated the scopes on 127.0.0.1
D, [2015-09-23T12:35:24.565531 #5848] DEBUG -- : Added 10.11.2.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:24.568465 #5848] DEBUG -- : Added 10.11.3.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:24.570471 #5848] DEBUG -- : Added 10.11.10.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:24.572348 #5848] DEBUG -- : Added 10.11.11.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:24.575361 #5848] DEBUG -- : Added 172.30.0.0/255.255.255.0 to 127.0.0.1
D, [2015-09-23T12:35:24.577320 #5848] DEBUG -- : Loading subnet data for 10.11.2.0/255.255.255.0
D, [2015-09-23T12:35:24.581157 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.2.0 show reservedip
I, [2015-09-23T12:35:24.652507 #5848]  INFO -- : Enumerated hosts on 10.11.2.0
D, [2015-09-23T12:35:24.653432 #5848] DEBUG -- : Lazy loaded 10.11.2.0/255.255.255.0 records
D, [2015-09-23T12:35:24.655381 #5848] DEBUG -- : Loading subnet data for 10.11.3.0/255.255.255.0
D, [2015-09-23T12:35:24.657274 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.3.0 show reservedip
I, [2015-09-23T12:35:24.729689 #5848]  INFO -- : Enumerated hosts on 10.11.3.0
D, [2015-09-23T12:35:24.730616 #5848] DEBUG -- : Lazy loaded 10.11.3.0/255.255.255.0 records
D, [2015-09-23T12:35:24.732557 #5848] DEBUG -- : Loading subnet data for 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:24.734614 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 show reservedip
I, [2015-09-23T12:35:24.805770 #5848]  INFO -- : Enumerated hosts on 10.11.10.0
D, [2015-09-23T12:35:24.807710 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.20
I, [2015-09-23T12:35:24.950267 #5848]  INFO -- : Queried 10.11.10.20 options
D, [2015-09-23T12:35:24.952239 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:24.954186 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:24.956102 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:24.958081 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"repos.corp.com"}
D, [2015-09-23T12:35:24.961940 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.20", :mac=>"00:1a:4a:c1:82:02", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"repos.corp.com"}
D, [2015-09-23T12:35:24.964944 #5848] DEBUG -- : Added 10.11.10.20 / 00:1a:4a:c1:82:02 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:24.966865 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.21
I, [2015-09-23T12:35:25.047878 #5848]  INFO -- : Queried 10.11.10.21 options
D, [2015-09-23T12:35:25.050069 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:25.052863 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:25.054794 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:25.056722 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-deploy.int.m-box
.de"}
D, [2015-09-23T12:35:25.059642 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.21", :mac=>"00:1a:4a:c1:82:03", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-deploy.corp.com"}
D, [2015-09-23T12:35:25.062637 #5848] DEBUG -- : Added 10.11.10.21 / 00:1a:4a:c1:82:03 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:25.066493 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.200
I, [2015-09-23T12:35:25.151498 #5848]  INFO -- : Queried 10.11.10.200 options
D, [2015-09-23T12:35:25.154378 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:25.156337 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:25.158311 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:25.160182 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"testlab.corp.com" 
}
D, [2015-09-23T12:35:25.163167 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.200", :mac=>"00:1a:4a:c1:82:04", :nextSe
rver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"testlab.corp.com"}
D, [2015-09-23T12:35:25.167082 #5848] DEBUG -- : Added 10.11.10.200 / 00:1a:4a:c1:82:04 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:25.169995 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.22
I, [2015-09-23T12:35:25.244192 #5848]  INFO -- : Queried 10.11.10.22 options
D, [2015-09-23T12:35:25.246184 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:25.248162 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:25.250038 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:25.252094 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"license01.int.m-box.d
e"}
D, [2015-09-23T12:35:25.254097 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.22", :mac=>"de:ad:04:fa:de:02", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"license01.corp.com"}
D, [2015-09-23T12:35:25.256854 #5848] DEBUG -- : Added 10.11.10.22 / de:ad:04:fa:de:02 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:25.258899 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.23
I, [2015-09-23T12:35:25.326292 #5848]  INFO -- : Queried 10.11.10.23 options
D, [2015-09-23T12:35:25.328251 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:25.330134 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:25.331118 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:25.333075 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-host.int.m-box.d
e"}
D, [2015-09-23T12:35:25.336052 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.23", :mac=>"00:1a:4a:c1:82:06", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"test-host.corp.com"}
D, [2015-09-23T12:35:25.338962 #5848] DEBUG -- : Added 10.11.10.23 / 00:1a:4a:c1:82:06 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:25.341840 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.16
I, [2015-09-23T12:35:25.412189 #5848]  INFO -- : Queried 10.11.10.16 options
D, [2015-09-23T12:35:25.414171 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:25.416095 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:25.418026 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:25.418950 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"puppetdb.corp.com
"}
D, [2015-09-23T12:35:25.422025 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.16", :mac=>"00:1a:4a:c1:82:08", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"puppetdb.corp.com"}
D, [2015-09-23T12:35:25.425056 #5848] DEBUG -- : Added 10.11.10.16 / 00:1a:4a:c1:82:08 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:25.426853 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.10.0 Show ReservedOptionValue 10.11.10.17
I, [2015-09-23T12:35:25.493245 #5848]  INFO -- : Queried 10.11.10.17 options
D, [2015-09-23T12:35:25.495217 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:25.497167 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:25.498092 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:25.500160 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"windeploy.int.m-box.d
e"}
D, [2015-09-23T12:35:25.502998 #5848] DEBUG -- : {:subnet=>10.11.10.0/255.255.255.0, :ip=>"10.11.10.17", :mac=>"00:1a:4a:c1:82:09", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"windeploy.corp.com"}
D, [2015-09-23T12:35:25.505964 #5848] DEBUG -- : Added 10.11.10.17 / 00:1a:4a:c1:82:09 to 10.11.10.0/255.255.255.0
D, [2015-09-23T12:35:25.507908 #5848] DEBUG -- : Lazy loaded 10.11.10.0/255.255.255.0 records
D, [2015-09-23T12:35:25.509950 #5848] DEBUG -- : Loading subnet data for 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:25.511735 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 show reservedip
I, [2015-09-23T12:35:25.581150 #5848]  INFO -- : Enumerated hosts on 10.11.11.0
D, [2015-09-23T12:35:25.583113 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 Show ReservedOptionValue 10.11.11.14
I, [2015-09-23T12:35:25.654338 #5848]  INFO -- : Queried 10.11.11.14 options
D, [2015-09-23T12:35:25.656320 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:25.658229 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:25.660248 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:25.662171 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"p500b.corp.com"}
D, [2015-09-23T12:35:25.663261 #5848] DEBUG -- : {:subnet=>10.11.11.0/255.255.255.0, :ip=>"10.11.11.14", :mac=>"6c:0b:84:0c:42:6b", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"p500b.corp.com"}
D, [2015-09-23T12:35:25.666093 #5848] DEBUG -- : Added 10.11.11.14 / 6c:0b:84:0c:42:6b to 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:25.668041 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 Show ReservedOptionValue 10.11.11.15
I, [2015-09-23T12:35:25.741279 #5848]  INFO -- : Queried 10.11.11.15 options
D, [2015-09-23T12:35:25.743210 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:25.745158 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:25.746239 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:25.748164 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"wstest01.corp.com
"}
D, [2015-09-23T12:35:25.752065 #5848] DEBUG -- : {:subnet=>10.11.11.0/255.255.255.0, :ip=>"10.11.11.15", :mac=>"00:1a:4a:c1:82:05", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"wstest01.corp.com"}
D, [2015-09-23T12:35:25.758828 #5848] DEBUG -- : Added 10.11.11.15 / 00:1a:4a:c1:82:05 to 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:25.760798 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 Show ReservedOptionValue 10.11.11.51
I, [2015-09-23T12:35:25.839916 #5848]  INFO -- : Queried 10.11.11.51 options
D, [2015-09-23T12:35:25.842809 #5848] DEBUG -- : found option nextServer
D, [2015-09-23T12:35:25.844866 #5848] DEBUG -- : found option filename
D, [2015-09-23T12:35:25.846777 #5848] DEBUG -- : found option install_path
D, [2015-09-23T12:35:25.849706 #5848] DEBUG -- : {:nextServer=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"fm-windepl.int.m-box.
de"}
D, [2015-09-23T12:35:25.854601 #5848] DEBUG -- : {:subnet=>10.11.11.0/255.255.255.0, :ip=>"10.11.11.51", :mac=>"00:1a:4a:c1:82:06", :nextSer
ver=>"10.11.10.15", :filename=>"pxelinux.0", :install_path=>"fm-windepl.corp.com"}
D, [2015-09-23T12:35:25.857460 #5848] DEBUG -- : Added 10.11.11.51 / 00:1a:4a:c1:82:06 to 10.11.11.0/255.255.255.0
D, [2015-09-23T12:35:25.860537 #5848] DEBUG -- : Lazy loaded 10.11.11.0/255.255.255.0 records
D, [2015-09-23T12:35:25.863389 #5848] DEBUG -- : Added fm-windepl.corp.com (10.11.11.51 / 00:1a:4a:c1:82:06) to 10.11.11.0/255.255.255.0

D, [2015-09-23T12:35:25.867292 #5848] DEBUG -- : executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.
0.0.1 scope 10.11.11.0 add reservedip 10.11.11.51 001a4ac18206 fm-windepl.corp.com
I, [2015-09-23T12:35:25.962020 #5848]  INFO -- : Vendor class not found
E, [2015-09-23T12:35:25.963922 #5848] ERROR -- : Failed to add DHCP reservation for fm-windepl.corp.com (10.11.11.51 / 00:1a:4a:c1:82:06
)Vendor class not found: ["The specified IP address or hardware address is being used by another client.\n"]
D, [2015-09-23T12:35:25.966908 #5848] DEBUG -- : c:/TheForeman/smart-proxy/modules/dhcp/providers/server/native_ms.rb:215:in `report'
c:/TheForeman/smart-proxy/modules/dhcp/providers/server/native_ms.rb:195:in `execute'
c:/TheForeman/smart-proxy/modules/dhcp/providers/server/native_ms.rb:35:in `addRecord'
c:/TheForeman/smart-proxy/modules/dhcp/dhcp_api.rb:96:in `block in <class:DhcpApi>'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `block in compile!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `[]'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (3 levels) in route!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:993:in `route_eval'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (2 levels) in route!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1014:in `block in process_route'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `catch'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `process_route'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:972:in `block in route!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `each'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `route!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1084:in `block in dispatch!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1081:in `dispatch!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `block in call!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `call!'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:894:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/methodoverride.rb:21:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/commonlogger.rb:33:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:218:in `call'
c:/TheForeman/smart-proxy/lib/proxy/log.rb:35:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/nulllogger.rb:9:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/head.rb:11:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/show_exceptions.rb:21:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:181:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:2021:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `block in call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1795:in `synchronize'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/urlmap.rb:65:in `block in call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `each'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
C:/Ruby200-x64/lib/ruby/gems/2.0.0/gems/rack-1.5.5/lib/rack/handler/webrick.rb:60:in `service'
C:/Ruby200-x64/lib/ruby/2.0.0/webrick/httpserver.rb:138:in `service'
C:/Ruby200-x64/lib/ruby/2.0.0/webrick/httpserver.rb:94:in `run'
C:/Ruby200-x64/lib/ruby/2.0.0/webrick/server.rb:295:in `block in start_thread'
fdff:dd77:2c2c:1110::15 - - [23/Sep/2015 12:35:26] "POST /dhcp/10.11.11.0 HTTP/1.1" 400 199 1.5423
foreman.corp.com - - [23/Sep/2015:12:35:24 W. Europe Daylight Time] "POST /dhcp/10.11.11.0 HTTP/1.1" 400 199
- -> /dhcp/10.11.11.0
Actions
Copy link
 #6

Updated by Dominic Cleal about 9 years ago

There's a DELETE buried in the middle, circa line 405, but it doesn't delete it so fails later on.

The smart proxy will only delete reservations and not leases, so it's probably believes the existing record as a lease (which it may be, you'd probably have to check). The MAC is already there with IP 10.11.11.51 so try deleting that in AD and it should then be able to add a new record.

Actions
Copy link
 #7

Updated by Daniel Helgenberger about 9 years ago

Dominic Cleal wrote:

There's a DELETE buried in the middle, circa line 405, but it doesn't delete it so fails later on.

There should be a line 

executing: c:\windows\system32\cmd.exe /c c:\Windows\System32\netsh.exe -c dhcp server 127.0.0.1 scope 10.11.11.0 delete reservedip 10.11.11.51 001a4ac18206 fm-windepl.corp.com

The smart proxy will only delete reservations and not leases, so it's probably believes the existing record as a lease (which it may be, you'd probably have to check). The MAC is already there with IP 10.11.11.51 so try deleting that in AD and it should then be able to add a new record.

I do not think so. Running the above command immediately before executing rebuild does fix the issue. I think I can do this myself and create a PR. Maybe change the addRecord method to call delRecord in https://github.com/theforeman/smart-proxy/blob/1.9-stable/modules/dhcp/providers/server/native_ms.rb. What do you think?
Also, I could not find delRecord in the develop branch any more..

Actions
Copy link
 #8

Updated by Anonymous about 9 years ago

I don't think the issue is on the smart-proxy side, for some reason Foreman didn't detect a conflict and consequently didn't attempt to remove the conflicting record. Blindly removing conflicting records before adding a new one is going to lead to issues: this would essentially ignore 'overwrite' flag for dhcp records and could lead to legitimate records being overwritten.

delRecord method you are looking for is here: https://github.com/theforeman/smart-proxy/blob/develop/modules/dhcp/providers/server/native_ms.rb#L23

Actions
Copy link
 #9

Updated by Daniel Helgenberger about 9 years ago

Dmitri Dolguikh wrote:

I don't think the issue is on the smart-proxy side, for some reason Foreman didn't detect a conflict and consequently didn't attempt to remove the conflicting record. Blindly removing conflicting records before adding a new one is going to lead to issues: this would essentially ignore 'overwrite' flag for dhcp records and could lead to legitimate records being overwritten.

Right; I found it in production.log. And I get what you mean, Dominic ;)

I did not mention I was running my hosts on oVirt. Ovirt did reuse MACs from deleted VMs; this caused the issue; there was a problem with one old reservation:

Added 10.11.10.23 / 00:1a:4a:c1:82:06 to 10.11.10.0/255.255.255.0

Good part: foreman did everything right. I think this was the issue from the start. I think I'll open an RFE against ovirt for that. I close this.

Actions
Copy link
 #10

Updated by Daniel Helgenberger about 9 years ago

Daniel Helgenberger wrote:

I close this.

Turns out I cannot do so, so if you please set it NOTABUG

Actions
Copy link
 #11

Updated by Dominic Cleal about 9 years ago

  • Status changed from New to Rejected

Ah yeah, duplicate MACs could cause a lot of problems I suppose. Glad you found it.

Actions
Copy link
 #12

Updated by Daniel Helgenberger about 9 years ago

Dominic Cleal wrote:

Ah yeah, duplicate MACs could cause a lot of problems I suppose.

Since we have the netsh exception:

["The specified IP address or hardware address is being used by another client.\n"]

Since my tests proved this can only be caused by a duplicate MAC it might be useful to raise this in a way preserving the original error message or return a more helpful then ERF12-6899 [ProxyAPI::ProxyException].

Actions
Copy link

Also available in: Atom PDF