Foreman » Smart Proxy

Dominic Cleal wrote:

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

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

Dominic Cleal wrote:

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

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

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

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

Dmitri Dolguikh wrote:

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

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

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

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

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

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

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

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

Here's the log from the second attempt:

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

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

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

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

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

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

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

Dmitri Dolguikh wrote:

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

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

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

I'm not sure what you mean.

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

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

Dmitri Dolguikh wrote:

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

I found the problem :)

This the current function in the dhcp_native_ms_main

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

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

      exec_result = execute(cmd, msg)
    end

It supposed to be like this:

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

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

      exec_result = execute(cmd, msg)
      nil
    end

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

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