Bug #17194
closed
Deleting a host doesn't delete ISC-DHCP entry
Added by Jon Skarpeteig over 7 years ago. Updated almost 7 years ago.
Description
Creating a host successfully creates ISC-DHCP entry through proxy, but doesn't delete it when deleting host
Updated by Dominic Cleal over 7 years ago
- Category set to DHCP
Could you provide Foreman and Smart Proxy logs please? I would like to determine if the deletion is at least attempted, and whether the Smart Proxy is failing to delete it or the request isn't made.
Are both Foreman and the Smart Proxy using 1.13.1?
Updated by Jon Skarpeteig over 7 years ago
There's no record in the foreman-proxy log of any delete attempts, only the omshell create ones. I was expecting something like this to be logged for omshell:
set name = "$1" open remove
foreman-proxy version is 1.12.3, while foreman is 1.13.1
I've seen this bug with previous versions as well. Not sure if it has ever worked
Updated by Jon Skarpeteig over 7 years ago
In case the occasional google search ends up here, here's my workaround:
#!/bin/sh
CONF=/etc/dhcp/dhcpd.conf
OMAPIPORT=`grep omapi-port $CONF | awk '{print $2}' | tr -d ";"`
KEYNAME=omapi_key
SECRET=`grep secret /etc/dhcp/dhcpd.conf | awk '{print $2}' | tr -d '"' | tr -d ";"`
omshell << EOF
server localhost
port $OMAPIPORT
key $KEYNAME $SECRET
connect
new host
set name = "$1"
open
remove
EOF
Updated by Dominic Cleal over 7 years ago
- Status changed from New to Need more information
Jon Skarpeteig wrote:
There's no record in the foreman-proxy log of any delete attempts, only the omshell create ones. I was expecting something like this to be logged for omshell:
Please provide the logs from Foreman and the Smart Proxy. Foreman debug logs will indicate which orchestration actions are queued, including DHCP deletion.
It's still unclear from your response whether a deletion request is received by the Smart Proxy or not - it's possible that the Smart Proxy doesn't call omshell if it determines there is nothing to delete.
Updated by Jon Skarpeteig over 7 years ago
I, [2016-11-03T09:42:08.482581 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:09:42:08 +0100] "GET /dhcp/10.0.25.0/unused_ip?from=10.0.25.2&to=10.0.25.255 HTTP/1.1" 200 20 12.1893 I, [2016-11-03T09:46:49.255915 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:09:46:49 +0100] "POST /dhcp/10.0.25.0 HTTP/1.1" 200 - 10.4441 I, [2016-11-03T09:47:19.600377 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:09:47:19 +0100] "DELETE /dhcp/10.0.25.0/00:50:56:bc:94:ac HTTP/1.1" 200 - 10.8920 E, [2016-11-03T09:47:48.187324 #6443] ERROR -- : DHCP record 10.0.25.0/00:50:56:bc:94:ac not found I, [2016-11-03T09:47:48.190079 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:09:47:48 +0100] "GET /dhcp/10.0.25.0/00:50:56:bc:94:ac HTTP/1.1" 404 50 10.7441 E, [2016-11-03T09:47:59.129899 #6443] ERROR -- : DHCP record 10.0.25.0/10.0.25.32 not found I, [2016-11-03T09:47:59.132260 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:09:47:59 +0100] "GET /dhcp/10.0.25.0/10.0.25.32 HTTP/1.1" 404 44 10.9366 E, [2016-11-03T09:48:45.896538 #6443] ERROR -- : DHCP record 10.0.25.0/00:50:56:bc:94:ac not found I, [2016-11-03T09:48:45.899114 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:09:48:45 +0100] "GET /dhcp/10.0.25.0/00:50:56:bc:94:ac HTTP/1.1" 404 50 10.7773 E, [2016-11-03T09:48:57.083744 #6443] ERROR -- : DHCP record 10.0.25.0/10.0.25.32 not found I, [2016-11-03T09:48:57.085908 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:09:48:57 +0100] "GET /dhcp/10.0.25.0/10.0.25.32 HTTP/1.1" 404 44 11.1799 I, [2016-11-03T09:49:11.079198 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:09:49:11 +0100] "POST /dhcp/10.0.25.0 HTTP/1.1" 200 - 10.8200 E, [2016-11-03T09:59:08.097977 #6443] ERROR -- : DHCP record 10.0.25.0/00:50:56:bc:ec:a4 not found I, [2016-11-03T09:59:08.100412 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:09:59:08 +0100] "DELETE /dhcp/10.0.25.0/00:50:56:bc:ec:a4 HTTP/1.1" 404 50 13.3780 I, [2016-11-03T10:00:07.165628 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:10:00:07 +0100] "GET /dhcp/10.0.25.0/unused_ip?from=10.0.25.2&to=10.0.25.255 HTTP/1.1" 200 20 16.5013 I, [2016-11-03T10:00:15.958298 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:10:00:15 +0100] "GET /dhcp/10.0.25.0/unused_ip?from=10.0.25.2&to=10.0.25.255 HTTP/1.1" 200 20 9.4217 E, [2016-11-03T10:01:02.822269 #6443] ERROR -- : Omshell failed: > > > > obj: <null> , > obj: host , > obj: host , name = "hardware.example.com" , > obj: host , name = "hardware.example.com" , ip-address = 0a:2f:19:27 , > obj: host , name = "hardware.example.com" , ip-address = 0a:2f:19:27 , hardware-address = 00:50:56:bc:cd:ac , > obj: host , name = "hardware.example.com" , ip-address = 0a:2f:19:27 , hardware-address = 00:50:56:bc:cd:ac , hardware-type = 1 , > obj: host , name = "hardware.example.com" , ip-address = 0a:2f:19:27 , hardware-address = 00:50:56:bc:cd:ac , hardware-type = 1 , statements = "filename = "pxelinux.0"; next-server = 0a:2f:18:0a; option host-name = "hardware.example.com";" , > can't open object: already exists , obj: host , name = "hardware.example.com" , ip-address = 0a:2f:19:27 , hardware-address = 00:50:56:bc:cd:ac , hardware-type = 1 , statements = "filename = "pxelinux.0"; next-server = 0a:2f:18:0a; option host-name = "hardware.example.com";" , > E, [2016-11-03T10:01:02.822626 #6443] ERROR -- : Failed to add DHCP reservation for hardware.example.com (10.0.25.39 / 00:50:56:bc:cd:ac): Entry already exists /usr/share/foreman-proxy/modules/dhcp_isc/dhcp_isc_main.rb:277:in `report' /usr/share/foreman-proxy/modules/dhcp_isc/dhcp_isc_main.rb:259:in `omcmd' /usr/share/foreman-proxy/modules/dhcp_isc/dhcp_isc_main.rb:73:in `add_record' /usr/share/foreman-proxy/modules/dhcp/dhcp_api.rb:89:in `block in <class:DhcpApi>' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1611:in `call' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1611:in `block in compile!' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:975:in `block (3 levels) in route!' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:994:in `route_eval' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:975:in `block (2 levels) in route!' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1015:in `block in process_route' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1013:in `catch' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1013:in `process_route' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:973:in `block in route!' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:972:in `each' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:972:in `route!' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1085:in `block in dispatch!' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1067:in `block in invoke' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1067:in `catch' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1067:in `invoke' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1082:in `dispatch!' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:907:in `block in call!' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1067:in `block in invoke' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1067:in `catch' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1067:in `invoke' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:907:in `call!' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:895:in `call' /usr/lib/ruby/vendor_ruby/rack/methodoverride.rb:22:in `call' /usr/lib/ruby/vendor_ruby/rack/commonlogger.rb:33:in `call' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:219:in `call' /usr/share/foreman-proxy/lib/proxy/log.rb:63:in `call' /usr/lib/ruby/vendor_ruby/rack/protection/xss_header.rb:18:in `call' /usr/lib/ruby/vendor_ruby/rack/protection/path_traversal.rb:16:in `call' /usr/lib/ruby/vendor_ruby/rack/protection/json_csrf.rb:18:in `call' /usr/lib/ruby/vendor_ruby/rack/protection/base.rb:49:in `call' /usr/lib/ruby/vendor_ruby/rack/protection/base.rb:49:in `call' /usr/lib/ruby/vendor_ruby/rack/protection/frame_options.rb:31:in `call' /usr/lib/ruby/vendor_ruby/rack/nulllogger.rb:9:in `call' /usr/lib/ruby/vendor_ruby/rack/head.rb:13:in `call' /usr/lib/ruby/vendor_ruby/sinatra/show_exceptions.rb:25:in `call' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:182:in `call' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:2013:in `call' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1487:in `block in call' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1787:in `synchronize' /usr/lib/ruby/vendor_ruby/sinatra/base.rb:1487:in `call' /usr/lib/ruby/vendor_ruby/rack/urlmap.rb:66:in `block in call' /usr/lib/ruby/vendor_ruby/rack/urlmap.rb:50:in `each' /usr/lib/ruby/vendor_ruby/rack/urlmap.rb:50:in `call' /usr/lib/ruby/vendor_ruby/rack/builder.rb:153:in `call' /usr/lib/ruby/vendor_ruby/rack/handler/webrick.rb:88:in `service' /usr/lib/ruby/2.3.0/webrick/httpserver.rb:140:in `service' /usr/lib/ruby/2.3.0/webrick/httpserver.rb:96:in `run' /usr/lib/ruby/2.3.0/webrick/server.rb:296:in `block in start_thread' I, [2016-11-03T10:01:02.824150 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:10:01:02 +0100] "POST /dhcp/10.0.25.0 HTTP/1.1" 400 112 7.8025 I, [2016-11-03T10:02:35.751035 #6443] INFO -- : 10.0.5.142 - - [03/Nov/2016:10:02:35 +0100] "GET /dhcp HTTP/1.1" 200 897 0.0181 I, [2016-11-03T10:02:35.983893 #6443] INFO -- : 10.0.5.142 - - [03/Nov/2016:10:02:35 +0100] "GET /favicon.ico HTTP/1.1" 404 593 0.0008 I, [2016-11-03T10:02:36.059180 #6443] INFO -- : 10.0.5.142 - - [03/Nov/2016:10:02:36 +0100] "GET /favicon.ico HTTP/1.1" 404 593 0.0004 I, [2016-11-03T10:02:57.059996 #6443] INFO -- : 10.0.5.142 - - [03/Nov/2016:10:02:57 +0100] "GET /dhcp/10.0.25.0 HTTP/1.1" 200 6491 7.9759 E, [2016-11-03T10:05:43.773408 #6443] ERROR -- : DHCP record 10.0.25.0/html not found I, [2016-11-03T10:05:43.775438 #6443] INFO -- : 10.0.5.142 - - [03/Nov/2016:10:05:43 +0100] "GET /dhcp/10.0.25.0/html HTTP/1.1" 404 37 8.4745 I, [2016-11-03T10:06:06.871987 #6443] INFO -- : 10.0.5.142 - - [03/Nov/2016:10:06:06 +0100] "GET /dhcp/10.0.25.0 HTTP/1.1" 200 6491 8.6294 I, [2016-11-03T10:07:18.899657 #6443] INFO -- : 10.0.5.142 - - [03/Nov/2016:10:07:18 +0100] "GET /dhcp/10.0.25.0 HTTP/1.1" 200 6409 9.3183 I, [2016-11-03T10:14:46.632769 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:10:14:46 +0100] "GET /dhcp/10.0.25.0/unused_ip?from=10.0.25.2&to=10.0.25.255 HTTP/1.1" 200 20 13.0769 I, [2016-11-03T10:14:58.296949 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:10:14:58 +0100] "GET /dhcp/10.0.25.0/unused_ip?from=10.0.25.2&to=10.0.25.255 HTTP/1.1" 200 20 12.2361 I, [2016-11-03T10:15:25.235584 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:10:15:25 +0100] "POST /dhcp/10.0.25.0 HTTP/1.1" 200 - 10.3917 I, [2016-11-03T10:38:27.647616 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:10:38:27 +0100] "GET /dhcp/10.0.25.0/00:50:56:bc:dd:7c HTTP/1.1" 200 168 9.5818 I, [2016-11-03T10:38:37.500037 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:10:38:37 +0100] "GET /dhcp/10.0.25.0/10.0.25.40 HTTP/1.1" 200 168 9.8464
Updated by Dominic Cleal over 7 years ago
Which part of the logs is the host deletion? (No corresponding Foreman logs.) What's going on in this paste - is it a host deletion followed by a host creation?
Which MAC and/or IP address should be removed? I see an error about adding a DHCP reservation, but both the IP and MAC differ from any of the other deletion entries.
Sorry, there isn't enough clear information here to even guess at what's going on, let alone define the bug.
Updated by Jon Skarpeteig over 7 years ago
The issue should be quite easy to reproduce. Just create a host, delete it, and create it again using the same hostname. Foreman will then (correctly) deny creating the DHCP record, as it exists already for the given hostname
I'm using VMware as compute target, so both the IP and MACs are dynamically defined, and should be unique for each host created
The resulting foreman-proxy log on the DHCP proxy is pasted above in it's entirety
Updated by Dominic Cleal over 7 years ago
- Project changed from Foreman to Smart Proxy
- Category changed from DHCP to DHCP
Yes, it appears to be a complete log, but it's unclear what it's a log of without the corresponding Foreman log or answers to the above questions.
There does appear to be a successful reservation creation and deletion, which could be a host creation/deletion:
I, [2016-11-03T09:46:49.255915 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:09:46:49 +0100] "POST /dhcp/10.0.25.0 HTTP/1.1" 200 - 10.4441
I, [2016-11-03T09:47:19.600377 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:09:47:19 +0100] "DELETE /dhcp/10.0.25.0/00:50:56:bc:94:ac HTTP/1.1" 200 - 10.8920
Followed by a successful creation, but unsuccessful deletion:
I, [2016-11-03T09:49:11.079198 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:09:49:11 +0100] "POST /dhcp/10.0.25.0 HTTP/1.1" 200 - 10.8200
E, [2016-11-03T09:59:08.097977 #6443] ERROR -- : DHCP record 10.0.25.0/00:50:56:bc:ec:a4 not found
I, [2016-11-03T09:59:08.100412 #6443] INFO -- : 10.0.24.10 - - [03/Nov/2016:09:59:08 +0100] "DELETE /dhcp/10.0.25.0/00:50:56:bc:ec:a4 HTTP/1.1" 404 50 13.3780
Followed by an unsuccessful creation, as something is already in use - probably the IP address, which is usually from the smart proxy, not vSphere.
If those are three separate host creations/deletions, then this may be an issue in the Smart Proxy module instead of Foreman, so changing the ticket project.
The smart proxy should detect the new DHCP reservation through monitoring the leases file after it's created. Is this file on the local filesystem?
If you enable debugging on the smart proxy while the reservation is created, the logs should then show the inotify behaviour, confirming whether the leases file was updated, assuming this is Linux. See https://theforeman.org/manuals/1.13/index.html#7.2Debugging for info on how to enable debug logs.
Updated by Anonymous almost 7 years ago
- Status changed from Need more information to Resolved
no reaction, closing.
Updated by Lukas Zapletal almost 7 years ago
Just for the record, we previously had similar report for image-based hosts (via API). It's being tracked under #9056. I am going to test this scenario but with libvirt.
Updated by Lukas Zapletal almost 7 years ago
- Related to Bug #9056: DHCP leases not deleted for image-based hosts via API added
Updated by Lukas Zapletal almost 7 years ago
Cannot reproduce with Foreman 1.15 and libvirt image-based provisioning. The host gets deleted immediately.