Foreman » Smart Proxy

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.

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

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.

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

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.

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

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.

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..

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

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.

Daniel Helgenberger wrote:

I close this.

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

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"]