Proxy DHCP failure prevents host record from saving

Support
#1

Are you sure the proxy logs are from the right one? If the host has
multiple subnets then Foreman could be contacting multiple smart proxies.

The IP addresses are different - the network 10.2.2.0 is listed in the
smart proxy log, but 10.230.100.0 is listed in the Foreman log.

It might be worth changing the proxy's log level to DEBUG to get more
information in its settings.yml.

··· On 16/05/16 22:50, Kyle Flavin wrote: > I'm having intermittent problems saving records on hosts which live on > subnets attached to a Foreman TFTP/DHCP proxy server. I'll make a > change to a host record (any change, such as overriding a parameter), > and try to submit the record. The form submits, but rather than taking > me back to the host detail page (ie: > https://foreman/hosts/myhost.mydomain.com), it takes me back to the > "host" tab on the edit page (ie: > https://foreman/hosts/myhost.mydomain.com/edit). No error messages are > displayed. I have to login to the foreman server, and into the proxy, > to see any errors. I'm trying to figure out what's preventing these > records from being saved. > > Here's what I see in the proxy logs, /var/log/foreman-proxy/proxy.log: > > > > > E,[2016-05-16T14:36:28.157102#19439] ERROR -- : Unable to add subnet > 10.2.2.0/255.255.255.0 > I,[2016-05-16T14:36:28.157650#19439] INFO -- : 10.1.1.1 - - > [16/May/2016 14:36:28] "GET /10.2.2.0/10.2.2.47 HTTP/1.1" 400 47 0.1811 > > > > > And here's what I see on the Foreman server, under > /var/log/foreman/production.log: > > > > 2016-05-1614:36:28[app][I]Failedto save: > 2016-05-1614:36:28[app][I]Redirectedto > https://foreman.mydomain.com/hosts/myhost.mydomain.com/edit > 2016-05-1614:36:28[app][W]ProxyAPIoperation FAILED > >ProxyAPI::ProxyException:ERF12-4395[ProxyAPI::ProxyException]:Unableto > retrieve DHCP entry > for10.230.100.47([RestClient::BadRequest]:400BadRequest)forproxy > https://smproxy1.cs.qai.expertcity.com:8443/dhcp

–
Dominic Cleal
dominic@cleal.org

#2

Yes, there is only one DHCP/TFTP proxy that we're using currently. I
modified the IP's by hand, but missed one apparently. I'll set the proxy
to debug to try and get more information.

··· On Monday, May 16, 2016 at 11:32:24 PM UTC-7, Dominic Cleal wrote: > > On 16/05/16 22:50, Kyle Flavin wrote: > > I'm having intermittent problems saving records on hosts which live on > > subnets attached to a Foreman TFTP/DHCP proxy server. I'll make a > > change to a host record (any change, such as overriding a parameter), > > and try to submit the record. The form submits, but rather than taking > > me back to the host detail page (ie: > > https://foreman/hosts/myhost.mydomain.com), it takes me back to the > > "host" tab on the edit page (ie: > > https://foreman/hosts/myhost.mydomain.com/edit). No error messages are > > displayed. I have to login to the foreman server, and into the proxy, > > to see any errors. I'm trying to figure out what's preventing these > > records from being saved. > > > > Here's what I see in the proxy logs, /var/log/foreman-proxy/proxy.log: > > > > > > > > > E,[2016-05-16T14:36:28.157102#19439] ERROR -- : Unable to add subnet > > 10.2.2.0/255.255.255.0 > > I,[2016-05-16T14:36:28.157650#19439] INFO -- : 10.1.1.1 - - > > [16/May/2016 14:36:28] "GET /10.2.2.0/10.2.2.47 HTTP/1.1" 400 47 0.1811 > > > > > > > > > And here's what I see on the Foreman server, under > > /var/log/foreman/production.log: > > > > > > > 2016-05-1614:36:28[app][I]Failedto save: > > 2016-05-1614:36:28[app][I]Redirectedto > > https://foreman.mydomain.com/hosts/myhost.mydomain.com/edit > > 2016-05-1614:36:28[app][W]ProxyAPIoperation FAILED > > >ProxyAPI::ProxyException:ERF12-4395[ProxyAPI::ProxyException]:Unableto > > retrieve DHCP entry > > for10.230.100.47([RestClient::BadRequest]:400BadRequest)forproxy > > https://smproxy1.cs.qai.expertcity.com:8443/dhcp > > Are you sure the proxy logs are from the right one? If the host has > multiple subnets then Foreman could be contacting multiple smart proxies. > > The IP addresses are different - the network 10.2.2.0 is listed in the > smart proxy log, but 10.230.100.0 is listed in the Foreman log. > > It might be worth changing the proxy's log level to DEBUG to get more > information in its settings.yml. > > -- > Dominic Cleal > dom...@cleal.org >
#3

Even with DEBUG turned on, the proxy logs don't show much (hostnames and
IP's below sanitized). It does seem to be related to DHCP, but I'm not
sure what exactly is failing. There are no conflicting records in
dhcpd.leases, and no conflicting DNS records. We're running Foreman 1.9.3.

D, [2016-05-18T08:36:14.195252 #11651] DEBUG – : accept: 10.2.3.12:35586
D, [2016-05-18T08:36:14.199297 #11651] DEBUG – : Rack::Handler::WEBrick is
invoked.
D, [2016-05-18T08:36:14.200200 #11651] DEBUG – : verifying remote client
10.2.3.12 against trusted_hosts
foremanserver1.mydomain.comforemanserver2.mydomain.comforeman.mydomain.comforemanserver1.mydomain.comsmproxy.mydomain.com
I, [2016-05-18T08:36:14.200862 #11651] INFO – : 10.2.3.12 - -
[18/May/2016 08:36:14] "GET /serverName HTTP/1.1" 200 47 0.0010

D, [2016-05-18T08:36:14.244066 #11651] DEBUG – : close: 10.2.3.12:35586
D, [2016-05-18T08:36:14.290020 #11651] DEBUG – : accept: 10.2.3.12:35587
D, [2016-05-18T08:36:14.294302 #11651] DEBUG – : Rack::Handler::WEBrick is
invoked.
D, [2016-05-18T08:36:14.295250 #11651] DEBUG – : verifying remote client
10.2.3.12 against trusted_hosts
foremanserver1.mydomain.comforemanserver2.mydomain.comforeman.mydomain.comforemanserver1.mydomain.comsmproxy.mydomain.com
D, [2016-05-18T08:36:14.295640 #11651] DEBUG – : Loading subnets for
127.0.0.1
D, [2016-05-18T08:36:14.295839 #11651] DEBUG – : Reading config file
/etc/dhcp/dhcpd.conf
D, [2016-05-18T08:36:14.296354 #11651] DEBUG – : Reading config file
/etc/dhcp/dhcpd.subnets
D, [2016-05-18T08:36:14.305936 #11651] DEBUG – : Added a subnet: 10.2.2.0
***** repeat for approx 30 different subnets ****
E, [2016-05-18T08:36:14.536398 #11651] ERROR – : Unable to add subnet
10.23.5.0/255.255.255.0
D, [2016-05-18T08:36:14.536527 #11651] DEBUG – : Unable to add subnet
10.23.5.0/255.255.255.0 (Proxy::DHCP::Error)
/usr/share/foreman-proxy/modules/dhcp_common/subnet_service.rb:15:in
add_subnet' /usr/share/foreman-proxy/modules/dhcp_common/subnet_service.rb:21:in
add_subnets'
/usr/share/foreman-proxy/modules/dhcp_common/subnet_service.rb:21:in each' /usr/share/foreman-proxy/modules/dhcp_common/subnet_service.rb:21:inadd_subnets'
/usr/share/foreman-proxy/modules/dhcp_isc/dhcp_isc_main.rb:194:in `
load_subnets'

/usr/share/foreman-proxy/modules/dhcp/dhcp_api.rb:13
/usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:461:in
instance_eval' /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:461:inbefore_filter!'
/usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:461:in each' /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:461:inbefore_filter!'
/usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:600:in
dispatch!' /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:411:incall!'
/usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:566:in
instance_eval' /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:566:ininvoke'
/usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:566:in catch' /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:566:ininvoke'
/usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:411:in call!' /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:399:incall'
/usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/methodoverride.rb:24:in
call' /usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/commonlogger.rb:18:incall'
/usr/share/foreman-proxy/lib/proxy/log.rb:60:in call' /usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/showexceptions.rb:24:incall'
/usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:979:in call' /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:1005:in
synchronize'
/usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:979:in call' /usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/urlmap.rb:47:incall'
/usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/urlmap.rb:41:in each' /usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/urlmap.rb:41:incall'
/usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/builder.rb:77:in call' /usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/content_length.rb:13:in
call'
/usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/handler/webrick.rb:48:in
service' /usr/lib/ruby/1.8/webrick/httpserver.rb:104:inservice'
/usr/lib/ruby/1.8/webrick/httpserver.rb:65:in run' /usr/lib/ruby/1.8/webrick/server.rb:173:instart_thread'
/usr/lib/ruby/1.8/webrick/server.rb:162:in start' /usr/lib/ruby/1.8/webrick/server.rb:162:instart_thread'
/usr/lib/ruby/1.8/webrick/server.rb:95:in start' /usr/lib/ruby/1.8/webrick/server.rb:92:ineach'
/usr/lib/ruby/1.8/webrick/server.rb:92:in start' /usr/lib/ruby/1.8/webrick/server.rb:23:instart'
/usr/lib/ruby/1.8/webrick/server.rb:82:in start' /usr/share/foreman-proxy/lib/launcher.rb:136:inlaunch'
/usr/share/foreman-proxy/lib/launcher.rb:136:in initialize' /usr/share/foreman-proxy/lib/launcher.rb:136:innew'
/usr/share/foreman-proxy/lib/launcher.rb:136:in `launch'
/usr/share/foreman-proxy/bin/smart-proxy:6
I, [2016-05-18T08:36:14.537167 #11651] INFO – : 10.2.3.12 - -
[18/May/2016 08:36:14] "GET /10.23.7.0/10.23.7.201 HTTP/1.1" 400 47 0.2422

D, [2016-05-18T08:36:14.579535 #11651] DEBUG – : close: 10.2.3.12:35587

#4

I just noticed that our smart proxy was upgraded to 1.11, while Foreman is
still on 1.9.3. This must be the issue.

··· On Wednesday, May 18, 2016 at 8:50:45 AM UTC-7, Kyle Flavin wrote: > > Even with DEBUG turned on, the proxy logs don't show much (hostnames and > IP's below sanitized). It does seem to be related to DHCP, but I'm not > sure what exactly is failing. There are no conflicting records in > dhcpd.leases, and no conflicting DNS records. We're running Foreman 1.9.3. > > > D, [2016-05-18T08:36:14.195252 #11651] DEBUG -- : accept: 10.2.3.12:35586 > D, [2016-05-18T08:36:14.199297 #11651] DEBUG -- : Rack::Handler::WEBrick > is invoked. > D, [2016-05-18T08:36:14.200200 #11651] DEBUG -- : verifying remote client > 10.2.3.12 against trusted_hosts > foremanserver1.mydomain.comforemanserver2.mydomain.comforeman.mydomain.comforemanserver1.mydomain.comsmproxy.mydomain.com > I, [2016-05-18T08:36:14.200862 #11651] INFO -- : 10.2.3.12 - - > [18/May/2016 08:36:14] "GET /serverName HTTP/1.1" 200 47 0.0010 > > D, [2016-05-18T08:36:14.244066 #11651] DEBUG -- : close: 10.2.3.12:35586 > D, [2016-05-18T08:36:14.290020 #11651] DEBUG -- : accept: 10.2.3.12:35587 > D, [2016-05-18T08:36:14.294302 #11651] DEBUG -- : Rack::Handler::WEBrick > is invoked. > D, [2016-05-18T08:36:14.295250 #11651] DEBUG -- : verifying remote client > 10.2.3.12 against trusted_hosts > foremanserver1.mydomain.comforemanserver2.mydomain.comforeman.mydomain.comforemanserver1.mydomain.comsmproxy.mydomain.com > D, [2016-05-18T08:36:14.295640 #11651] DEBUG -- : Loading subnets for > 127.0.0.1 > D, [2016-05-18T08:36:14.295839 #11651] DEBUG -- : Reading config file > /etc/dhcp/dhcpd.conf > D, [2016-05-18T08:36:14.296354 #11651] DEBUG -- : Reading config file > /etc/dhcp/dhcpd.subnets > D, [2016-05-18T08:36:14.305936 #11651] DEBUG -- : Added a subnet: 10.2.2.0 > ***** repeat for approx 30 different subnets **** > E, [2016-05-18T08:36:14.536398 #11651] ERROR -- : Unable to add subnet > 10.23.5.0/255.255.255.0 > D, [2016-05-18T08:36:14.536527 #11651] DEBUG -- : Unable to add subnet > 10.23.5.0/255.255.255.0 (Proxy::DHCP::Error) > /usr/share/foreman-proxy/modules/dhcp_common/subnet_service.rb:15:in > `add_subnet' > /usr/share/foreman-proxy/modules/dhcp_common/subnet_service.rb:21:in ` > add_subnets' > /usr/share/foreman-proxy/modules/dhcp_common/subnet_service.rb:21:in `each' > /usr/share/foreman-proxy/modules/dhcp_common/subnet_service.rb:21:in > `add_subnets' > /usr/share/foreman-proxy/modules/dhcp_isc/dhcp_isc_main.rb:194:in ` > load_subnets' > > /usr/share/foreman-proxy/modules/dhcp/dhcp_api.rb:13 > /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:461:in > `instance_eval' > /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:461:in > `before_filter!' > /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:461:in `each' > /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:461:in > `before_filter!' > /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:600:in > `dispatch!' > /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:411:in `call!' > /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:566:in > `instance_eval' > /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:566:in > `invoke' > /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:566:in `catch' > /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:566:in `invoke' > /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:411:in `call!' > /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:399:in `call' > /usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/methodoverride.rb:24:in > `call' > /usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/commonlogger.rb:18:in > `call' > /usr/share/foreman-proxy/lib/proxy/log.rb:60:in `call' > /usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/showexceptions.rb:24:in > `call' > /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:979:in `call' > /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:1005:in ` > synchronize' > /usr/lib/ruby/gems/1.8/gems/sinatra-1.0/lib/sinatra/base.rb:979:in `call' > /usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/urlmap.rb:47:in `call' > /usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/urlmap.rb:41:in `each' > /usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/urlmap.rb:41:in `call' > /usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/builder.rb:77:in `call' > /usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/content_length.rb:13:in ` > call' > /usr/lib/ruby/gems/1.8/gems/rack-1.1.0/lib/rack/handler/webrick.rb:48:in > `service' > /usr/lib/ruby/1.8/webrick/httpserver.rb:104:in `service' > /usr/lib/ruby/1.8/webrick/httpserver.rb:65:in `run' > /usr/lib/ruby/1.8/webrick/server.rb:173:in `start_thread' > /usr/lib/ruby/1.8/webrick/server.rb:162:in `start' > /usr/lib/ruby/1.8/webrick/server.rb:162:in `start_thread' > /usr/lib/ruby/1.8/webrick/server.rb:95:in `start' > /usr/lib/ruby/1.8/webrick/server.rb:92:in `each' > /usr/lib/ruby/1.8/webrick/server.rb:92:in `start' > /usr/lib/ruby/1.8/webrick/server.rb:23:in `start' > /usr/lib/ruby/1.8/webrick/server.rb:82:in `start' > /usr/share/foreman-proxy/lib/launcher.rb:136:in `launch' > /usr/share/foreman-proxy/lib/launcher.rb:136:in `initialize' > /usr/share/foreman-proxy/lib/launcher.rb:136:in `new' > /usr/share/foreman-proxy/lib/launcher.rb:136:in `launch' > /usr/share/foreman-proxy/bin/smart-proxy:6 > I, [2016-05-18T08:36:14.537167 #11651] INFO -- : 10.2.3.12 - - > [18/May/2016 08:36:14] "GET /10.23.7.0/10.23.7.201 HTTP/1.1" 400 47 0.2422 > > D, [2016-05-18T08:36:14.579535 #11651] DEBUG -- : close: 10.2.3.12:35587 > > >