Foreman » Smart Proxy

We don't have any smart proxy plugins installed. I'll try the debugging step.

launcher.rb only exists in latest smart-proxy code - can I patch the trap code in somewhere else in 1.9.2 ?

Here you go, this is the same patch designed for 1.9 - changing smart_proxy.rb instead:

https://github.com/theforeman/smart-proxy/compare/theforeman:1.9-stable...domcleal:1.9-stable-ttin.patch

Starting thread dump for current Ruby process =============================================

Thread TID-11812860
/usr/share/foreman-proxy/lib/smart_proxy.rb:151:in `block (2 levels) in launch'
/usr/share/foreman-proxy/lib/smart_proxy.rb:149:in `each'
/usr/share/foreman-proxy/lib/smart_proxy.rb:149:in `block in launch'
/usr/share/foreman-proxy/lib/smart_proxy.rb:155:in `call'
/usr/share/foreman-proxy/lib/smart_proxy.rb:155:in `join'
/usr/share/foreman-proxy/lib/smart_proxy.rb:155:in `launch'
./bin/smart-proxy:6:in `<main>'

Thread TID-11683980
/usr/lib/ruby/1.9.1/webrick/server.rb:98:in `block in start'
/usr/lib/ruby/1.9.1/webrick/server.rb:22:in `start'
/usr/lib/ruby/1.9.1/webrick/server.rb:89:in `start'
/usr/lib/ruby/vendor_ruby/rack/handler/webrick.rb:14:in `run'
/usr/lib/ruby/vendor_ruby/rack/server.rb:264:in `start'
/usr/share/foreman-proxy/lib/smart_proxy.rb:137:in `block in launch'

Thread TID-16558360
/usr/lib/ruby/1.9.1/webrick/utils.rb:184:in `block in initialize'

Thread TID-16412380
/usr/lib/ruby/1.9.1/monitor.rb:185:in `mon_enter'
/usr/lib/ruby/1.9.1/monitor.rb:209:in `mon_synchronize'
/usr/lib/ruby/1.9.1/logger.rb:559:in `write'
/usr/lib/ruby/1.9.1/logger.rb:377:in `add'
/usr/lib/ruby/1.9.1/logger.rb:399:in `debug'
/usr/share/foreman-proxy/modules/dhcp/subnet.rb:115:in `add_record'
/usr/share/foreman-proxy/modules/dhcp/record.rb:19:in `initialize'
/usr/share/foreman-proxy/modules/dhcp/record/lease.rb:12:in `initialize'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:122:in `new'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:122:in `block in loadSubnetData'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:98:in `scan'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:98:in `loadSubnetData'
/usr/share/foreman-proxy/modules/dhcp/subnet.rb:65:in `load'
/usr/share/foreman-proxy/modules/dhcp/subnet.rb:75:in `records'
/usr/share/foreman-proxy/modules/dhcp/server.rb:79:in `block in find_record'
/usr/share/foreman-proxy/modules/dhcp/server.rb:78:in `each'
/usr/share/foreman-proxy/modules/dhcp/server.rb:78:in `find_record'
/usr/share/foreman-proxy/modules/dhcp/dhcp_api.rb:84:in `block in <class:DhcpApi>'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1541:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1541:in `block in compile!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `[]'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `block (3 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:966:in `route_eval'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `block (2 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:987:in `block in process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:985:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:985:in `process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:948:in `block in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:947:in `each'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:947:in `route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1059:in `block in dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1056:in `dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:882:in `block in call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:882:in `call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:870:in `call'
/usr/lib/ruby/vendor_ruby/rack/methodoverride.rb:21:in `call'
/usr/lib/ruby/vendor_ruby/rack/commonlogger.rb:33:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:212:in `call'
/usr/share/foreman-proxy/lib/proxy/log.rb:35: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:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/base.rb:50: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:11:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/showexceptions.rb:21:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:175:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1949:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1449:in `block in call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1726:in `synchronize'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1449:in `call'
/usr/lib/ruby/vendor_ruby/rack/builder.rb:138:in `call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:65: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:138:in `call'
/usr/lib/ruby/vendor_ruby/rack/handler/webrick.rb:60:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:138:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:94:in `run'
/usr/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'

Thread TID-70152626059540
/usr/lib/ruby/1.9.1/logger.rb:568:in `block in write'
/usr/lib/ruby/1.9.1/monitor.rb:211:in `mon_synchronize'
/usr/lib/ruby/1.9.1/logger.rb:559:in `write'
/usr/lib/ruby/1.9.1/logger.rb:377:in `add'
/usr/lib/ruby/1.9.1/logger.rb:399:in `debug'
/usr/share/foreman-proxy/modules/dhcp/subnet.rb:115:in `add_record'
/usr/share/foreman-proxy/modules/dhcp/record.rb:19:in `initialize'
/usr/share/foreman-proxy/modules/dhcp/record/lease.rb:12:in `initialize'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:122:in `new'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:122:in `block in loadSubnetData'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:98:in `scan'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:98:in `loadSubnetData'
/usr/share/foreman-proxy/modules/dhcp/subnet.rb:65:in `load'
/usr/share/foreman-proxy/modules/dhcp/subnet.rb:75:in `records'
/usr/share/foreman-proxy/modules/dhcp/server.rb:79:in `block in find_record'
/usr/share/foreman-proxy/modules/dhcp/server.rb:78:in `each'
/usr/share/foreman-proxy/modules/dhcp/server.rb:78:in `find_record'
/usr/share/foreman-proxy/modules/dhcp/dhcp_api.rb:84:in `block in <class:DhcpApi>'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1541:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1541:in `block in compile!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `[]'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `block (3 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:966:in `route_eval'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `block (2 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:987:in `block in process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:985:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:985:in `process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:948:in `block in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:947:in `each'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:947:in `route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1059:in `block in dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1056:in `dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:882:in `block in call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:882:in `call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:870:in `call'
/usr/lib/ruby/vendor_ruby/rack/methodoverride.rb:21:in `call'
/usr/lib/ruby/vendor_ruby/rack/commonlogger.rb:33:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:212:in `call'
/usr/share/foreman-proxy/lib/proxy/log.rb:35: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:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/base.rb:50: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:11:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/showexceptions.rb:21:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:175:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1949:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1449:in `block in call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1726:in `synchronize'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1449:in `call'
/usr/lib/ruby/vendor_ruby/rack/builder.rb:138:in `call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:65: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:138:in `call'
/usr/lib/ruby/vendor_ruby/rack/handler/webrick.rb:60:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:138:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:94:in `run'
/usr/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'

Thread TID-70152625007680
/usr/lib/ruby/1.9.1/monitor.rb:185:in `mon_enter'
/usr/lib/ruby/1.9.1/monitor.rb:209:in `mon_synchronize'
/usr/lib/ruby/1.9.1/logger.rb:559:in `write'
/usr/lib/ruby/1.9.1/logger.rb:377:in `add'
/usr/lib/ruby/1.9.1/logger.rb:399:in `debug'
/usr/share/foreman-proxy/modules/dhcp/subnet.rb:115:in `add_record'
/usr/share/foreman-proxy/modules/dhcp/record.rb:19:in `initialize'
/usr/share/foreman-proxy/modules/dhcp/record/lease.rb:12:in `initialize'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:122:in `new'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:122:in `block in loadSubnetData'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:98:in `scan'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:98:in `loadSubnetData'
/usr/share/foreman-proxy/modules/dhcp/subnet.rb:65:in `load'
/usr/share/foreman-proxy/modules/dhcp/subnet.rb:75:in `records'
/usr/share/foreman-proxy/modules/dhcp/server.rb:79:in `block in find_record'
/usr/share/foreman-proxy/modules/dhcp/server.rb:78:in `each'
/usr/share/foreman-proxy/modules/dhcp/server.rb:78:in `find_record'
/usr/share/foreman-proxy/modules/dhcp/dhcp_api.rb:84:in `block in <class:DhcpApi>'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1541:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1541:in `block in compile!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `[]'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `block (3 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:966:in `route_eval'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `block (2 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:987:in `block in process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:985:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:985:in `process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:948:in `block in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:947:in `each'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:947:in `route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1059:in `block in dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1056:in `dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:882:in `block in call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:882:in `call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:870:in `call'
/usr/lib/ruby/vendor_ruby/rack/methodoverride.rb:21:in `call'
/usr/lib/ruby/vendor_ruby/rack/commonlogger.rb:33:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:212:in `call'
/usr/share/foreman-proxy/lib/proxy/log.rb:35: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:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/base.rb:50: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:11:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/showexceptions.rb:21:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:175:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1949:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1449:in `block in call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1726:in `synchronize'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1449:in `call'
/usr/lib/ruby/vendor_ruby/rack/builder.rb:138:in `call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:65: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:138:in `call'
/usr/lib/ruby/vendor_ruby/rack/handler/webrick.rb:60:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:138:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:94:in `run'
/usr/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'

Don't know if it's relevant or not, but on foregrounded startup we also get :

[2015-11-04 14:45:31] INFO WEBrick 1.3.1
[2015-11-04 14:45:31] INFO ruby 1.9.3 (2013-11-22) [x86_64-linux]
[2015-11-04 14:45:31] WARN TCPServer Error: Address already in use - bind(2)

There's definitely only one smart proxy process running

Our lease file is around 3MB, and the environment is currently completely static so there shouldn't be any add_record calls. We see a lot of GET calls in the logs :

GET /dhcp/10.10.160.0/10.10.160.106 HTTP/1.1" 200 130 - -> /dhcp/10.10.160.0/10.10.160.106

We have around 150 hosts, split across two environments with different proxies.

Anecdotally it did seem like the DHCP records are being validated during puppet runs for some reason - is this the case ?

Yes, I've got DEBUG logging turned on at the minute.

In case it's useful, here's the dump using latest github code :

Starting thread dump for current Ruby process =============================================

Thread TID-16082940
/root/smart-proxy/lib/launcher.rb:14:in `block (2 levels) in <class:Launcher>'
/root/smart-proxy/lib/launcher.rb:12:in `each'
/root/smart-proxy/lib/launcher.rb:12:in `block in <class:Launcher>'
/root/smart-proxy/lib/launcher.rb:139:in `call'
/root/smart-proxy/lib/launcher.rb:139:in `join'
/root/smart-proxy/lib/launcher.rb:139:in `launch'
./bin/smart-proxy:6:in `<main>'

Thread TID-23501380
/usr/lib/ruby/1.9.1/webrick/server.rb:98:in `block in start'
/usr/lib/ruby/1.9.1/webrick/server.rb:22:in `start'
/usr/lib/ruby/1.9.1/webrick/server.rb:89:in `start'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/handler/webrick.rb:14:in `run'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/server.rb:264:in `start'
/root/smart-proxy/lib/launcher.rb:124:in `block in launch'

Thread TID-23225340
/usr/lib/ruby/1.9.1/monitor.rb:185:in `mon_enter'
/usr/lib/ruby/1.9.1/monitor.rb:209:in `mon_synchronize'
/usr/lib/ruby/1.9.1/logger.rb:559:in `write'
/usr/lib/ruby/1.9.1/logger.rb:377:in `add'
/usr/lib/ruby/1.9.1/logger.rb:399:in `debug'
/root/smart-proxy/modules/dhcp/subnet_service.rb:64:in `add_host'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:126:in `block in initialize_memory_store_with_dhcp_records'185.43.217.33 - - [04/Nov/2015:15:31:25 GMT] "GET /tftp/serverName HTTP/1.1" 200 17

- -> /tftp/serverName
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `each'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `initialize_memory_store_with_dhcp_records'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:147:in `loadSubnetData'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:42:in `load_subnet_data'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:95:in `block in <class:DhcpApi>'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `block in compile!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `[]'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (3 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:993:in `route_eval'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (2 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1014:in `block in process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:972:in `block in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `each'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1084:in `block in dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1081:in `dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `block in call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:894:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/methodoverride.rb:21:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/commonlogger.rb:33:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:218:in `call'
/root/smart-proxy/lib/proxy/log.rb:58:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/nulllogger.rb:9:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/head.rb:11:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/show_exceptions.rb:21:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:181:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:2021:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `block in call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1795:in `synchronize'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:65:in `block in call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `each'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/handler/webrick.rb:60:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:138:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:94:in `run'
/usr/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'

Thread TID-23454700
/usr/lib/ruby/1.9.1/webrick/utils.rb:184:in `block in initialize'

Thread TID-23326740
/usr/lib/ruby/1.9.1/monitor.rb:185:in `mon_enter'
/usr/lib/ruby/1.9.1/monitor.rb:209:in `mon_synchronize'
/usr/lib/ruby/1.9.1/logger.rb:559:in `write'
/usr/lib/ruby/1.9.1/logger.rb:377:in `add'
/usr/lib/ruby/1.9.1/logger.rb:399:in `debug'
/root/smart-proxy/modules/dhcp/subnet_service.rb:64:in `add_host'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:126:in `block in initialize_memory_store_with_dhcp_records'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `each'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `initialize_memory_store_with_dhcp_records'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:147:in `loadSubnetData'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:42:in `load_subnet_data'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:95:in `block in <class:DhcpApi>'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `block in compile!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `[]'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (3 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:993:in `route_eval'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (2 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1014:in `block in process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:972:in `block in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `each'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1084:in `block in dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1081:in `dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `block in call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:894:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/methodoverride.rb:21:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/commonlogger.rb:33:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:218:in `call'
/root/smart-proxy/lib/proxy/log.rb:58:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/nulllogger.rb:9:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/head.rb:11:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/show_exceptions.rb:21:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:181:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:2021:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `block in call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1795:in `synchronize'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:65:in `block in call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `each'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/handler/webrick.rb:60:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:138:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:94:in `run'
/usr/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'

Thread TID-70134366617260
/usr/lib/ruby/1.9.1/monitor.rb:185:in `mon_enter'
/usr/lib/ruby/1.9.1/monitor.rb:209:in `mon_synchronize'
/usr/lib/ruby/1.9.1/logger.rb:559:in `write'
/usr/lib/ruby/1.9.1/logger.rb:377:in `add'
/usr/lib/ruby/1.9.1/logger.rb:399:in `debug'
/root/smart-proxy/modules/dhcp/subnet_service.rb:64:in `add_host'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:126:in `block in initialize_memory_store_with_dhcp_records'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `each'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `initialize_memory_store_with_dhcp_records'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:147:in `loadSubnetData'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:42:in `load_subnet_data'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:95:in `block in <class:DhcpApi>'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `block in compile!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `[]'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (3 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:993:in `route_eval'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (2 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1014:in `block in process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:972:in `block in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `each'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1084:in `block in dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1081:in `dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `block in call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:894:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/methodoverride.rb:21:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/commonlogger.rb:33:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:218:in `call'
/root/smart-proxy/lib/proxy/log.rb:58:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/nulllogger.rb:9:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/head.rb:11:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/show_exceptions.rb:21:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:181:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:2021:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `block in call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1795:in `synchronize'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:65:in `block in call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `each'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/handler/webrick.rb:60:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:138:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:94:in `run'
/usr/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'

Thread TID-70134373785180
/usr/lib/ruby/1.9.1/monitor.rb:185:in `mon_enter'
/usr/lib/ruby/1.9.1/monitor.rb:209:in `mon_synchronize'
/usr/lib/ruby/1.9.1/logger.rb:559:in `write'
/usr/lib/ruby/1.9.1/logger.rb:377:in `add'
/usr/lib/ruby/1.9.1/logger.rb:399:in `debug'
/root/smart-proxy/modules/dhcp/subnet_service.rb:64:in `add_host'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:126:in `block in initialize_memory_store_with_dhcp_records'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `each'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `initialize_memory_store_with_dhcp_records'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:147:in `loadSubnetData'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:42:in `load_subnet_data'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:95:in `block in <class:DhcpApi>'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `block in compile!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `[]'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (3 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:993:in `route_eval'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (2 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1014:in `block in process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:972:in `block in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `each'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1084:in `block in dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1081:in `dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `block in call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:894:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/methodoverride.rb:21:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/commonlogger.rb:33:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:218:in `call'
/root/smart-proxy/lib/proxy/log.rb:58:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/nulllogger.rb:9:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/head.rb:11:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/show_exceptions.rb:21:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:181:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:2021:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `block in call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1795:in `synchronize'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:65:in `block in call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `each'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/handler/webrick.rb:60:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:138:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:94:in `run'
/usr/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'

Thread TID-70134373711540
/usr/lib/ruby/1.9.1/monitor.rb:185:in `mon_enter'
/usr/lib/ruby/1.9.1/monitor.rb:209:in `mon_synchronize'
/usr/lib/ruby/1.9.1/logger.rb:559:in `write'
/usr/lib/ruby/1.9.1/logger.rb:377:in `add'
/usr/lib/ruby/1.9.1/logger.rb:399:in `debug'
/root/smart-proxy/modules/dhcp/subnet_service.rb:64:in `add_host'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:126:in `block in initialize_memory_store_with_dhcp_records'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `each'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `initialize_memory_store_with_dhcp_records'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:147:in `loadSubnetData'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:42:in `load_subnet_data'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:95:in `block in <class:DhcpApi>'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `block in compile!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `[]'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (3 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:993:in `route_eval'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (2 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1014:in `block in process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:972:in `block in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `each'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1084:in `block in dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1081:in `dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `block in call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:894:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/methodoverride.rb:21:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/commonlogger.rb:33:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:218:in `call'
/root/smart-proxy/lib/proxy/log.rb:58:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/nulllogger.rb:9:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/head.rb:11:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/show_exceptions.rb:21:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:181:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:2021:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `block in call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1795:in `synchronize'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:65:in `block in call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `each'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/handler/webrick.rb:60:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:138:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:94:in `run'
/usr/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'

Thread TID-70134368164880
/usr/lib/ruby/1.9.1/monitor.rb:185:in `mon_enter'
/usr/lib/ruby/1.9.1/monitor.rb:209:in `mon_synchronize'
/usr/lib/ruby/1.9.1/logger.rb:559:in `write'
/usr/lib/ruby/1.9.1/logger.rb:377:in `add'
/usr/lib/ruby/1.9.1/logger.rb:399:in `debug'
/root/smart-proxy/modules/dhcp/subnet_service.rb:64:in `add_host'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:126:in `block in initialize_memory_store_with_dhcp_records'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `each'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `initialize_memory_store_with_dhcp_records'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:147:in `loadSubnetData'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:42:in `load_subnet_data'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:95:in `block in <class:DhcpApi>'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `block in compile!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `[]'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (3 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:993:in `route_eval'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (2 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1014:in `block in process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:972:in `block in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `each'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1084:in `block in dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1081:in `dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `block in call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:894:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/methodoverride.rb:21:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/commonlogger.rb:33:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:218:in `call'
/root/smart-proxy/lib/proxy/log.rb:58:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/nulllogger.rb:9:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/head.rb:11:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/show_exceptions.rb:21:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:181:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:2021:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `block in call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1795:in `synchronize'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:65:in `block in call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `each'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/handler/webrick.rb:60:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:138:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:94:in `run'
/usr/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'

Thread TID-70134233897060
/usr/lib/ruby/1.9.1/monitor.rb:185:in `mon_enter'
/usr/lib/ruby/1.9.1/monitor.rb:209:in `mon_synchronize'
/usr/lib/ruby/1.9.1/logger.rb:559:in `write'
/usr/lib/ruby/1.9.1/logger.rb:377:in `add'
/usr/lib/ruby/1.9.1/logger.rb:399:in `debug'
/root/smart-proxy/modules/dhcp/subnet_service.rb:64:in `add_host'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:126:in `block in initialize_memory_store_with_dhcp_records'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `each'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `initialize_memory_store_with_dhcp_records'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:147:in `loadSubnetData'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:42:in `load_subnet_data'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:95:in `block in <class:DhcpApi>'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `block in compile!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `[]'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (3 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:993:in `route_eval'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (2 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1014:in `block in process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:972:in `block in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `each'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1084:in `block in dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1081:in `dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `block in call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:894:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/methodoverride.rb:21:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/commonlogger.rb:33:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:218:in `call'
/root/smart-proxy/lib/proxy/log.rb:58:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/nulllogger.rb:9:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/head.rb:11:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/show_exceptions.rb:21:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:181:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:2021:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `block in call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1795:in `synchronize'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:65:in `block in call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `each'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/handler/webrick.rb:60:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:138:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:94:in `run'
/usr/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'

Thread TID-70134236683340
/usr/lib/ruby/1.9.1/monitor.rb:185:in `mon_enter'
/usr/lib/ruby/1.9.1/monitor.rb:209:in `mon_synchronize'
/usr/lib/ruby/1.9.1/logger.rb:559:in `write'
/usr/lib/ruby/1.9.1/logger.rb:377:in `add'
/usr/lib/ruby/1.9.1/logger.rb:399:in `debug'
/root/smart-proxy/modules/dhcp/subnet_service.rb:64:in `add_host'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:126:in `block in initialize_memory_store_with_dhcp_records'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `each'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:110:in `initialize_memory_store_with_dhcp_records'
/root/smart-proxy/modules/dhcp/providers/server/isc.rb:147:in `loadSubnetData'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:42:in `load_subnet_data'
/root/smart-proxy/modules/dhcp/dhcp_api.rb:95:in `block in <class:DhcpApi>'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `block in compile!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `[]'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (3 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:993:in `route_eval'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:974:in `block (2 levels) in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1014:in `block in process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `process_route'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:972:in `block in route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `each'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:971:in `route!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1084:in `block in dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1081:in `dispatch!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `block in call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `call!'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:894:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/methodoverride.rb:21:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/commonlogger.rb:33:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:218:in `call'
/root/smart-proxy/lib/proxy/log.rb:58:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/var/lib/gems/1.9.1/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/nulllogger.rb:9:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/head.rb:11:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/show_exceptions.rb:21:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:181:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:2021:in `call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `block in call'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1795:in `synchronize'
/var/lib/gems/1.9.1/gems/sinatra-1.4.6/lib/sinatra/base.rb:1486:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:65:in `block in call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `each'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/urlmap.rb:50:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/builder.rb:138:in `call'
/var/lib/gems/1.9.1/gems/rack-1.5.5/lib/rack/handler/webrick.rb:60:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:138:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:94:in `run'
/usr/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'

Matt Jarvis wrote:

Anecdotally it did seem like the DHCP records are being validated during puppet runs for some reason - is this the case ?

Yes, that was my suspicion, but I can't remember where I saw it change. Either the fact or report importers, probably when importing network interfaces. Traditionally Foreman didn't do orchestration (inc. DHCP) during fact imports for fear of changing something incorrectly, but the load should clearly be a concern too.

That would explain a lot if that is the case. We've been trying to debug puppet timeouts for weeks now, and have been round the houses with looking at Foreman performance, PuppetDB performance etc. We'd pretty much narrowed it down to fact uploads into Foreman, and I just noticed last week that there was a proxy call timeout in Foreman just before a failed run.

And as you know I also just raised an issue about importing network interfaces ;)

I've had a poke around in the code but it's not obvious where that might be happening. Can you give me a steer where to start looking for DHCP validation calls during fact import if that looks like the issue ?

Look on the foreman side. I think the calls to smart-proxy are being triggered here, when save! is being called: https://github.com/theforeman/foreman/blob/develop/app/models/host/base.rb#L148 (which is called from here: https://github.com/theforeman/foreman/blob/develop/app/models/host/base.rb#L124). If you look at Nic::Managed (https://github.com/theforeman/foreman/blob/develop/app/models/nic/managed.rb) you'll see that it includes Orchestration::DHCP (https://github.com/theforeman/foreman/blob/develop/app/models/concerns/orchestration/dhcp.rb). I think the method responsible for the calls to the proxy is dhcp_conflict_detected? (https://github.com/theforeman/foreman/blob/develop/app/models/concerns/orchestration/dhcp.rb#L173) which is triggered after record validation (before it is saved).

I may well be being dense, but why would you want to check this unless you know it's changed ? I can't think of a scenario where that would be the case - if my interface is set to DHCP, I've got my address from the DHCP server, therefore I don't need to check the DHCP server for conflicts because it's assigned that address to me.

Changing dhcp_conflict_detected? to :

def dhcp_conflict_detected?
  # we can't do any dhcp based validations when our MAC address is defined afterwards (e.g. in vm creation)
    return false if mac.blank? or hostname.blank?
    return false unless dhcp? and dhcp_update_required?

if dhcp_record and dhcp_record.conflicting? and (not overwrite?)
      failure(_("DHCP records %s already exists") % dhcp_record.conflicts.to_sentence, nil, :conflict)
      return true
    end
    false
  end

seems to work, load is drastically reduced on the proxies and stuff still seems to function, but as I say I may well be missing something here.

Keep in mind this is also used during host creation, for which it makes sense. I think your change breaks host creation (@old isn't going to be initialized for new records). One way to resolve this issue is to speed up dhcp proxy, which is on my plate. You can help out by doing PR reviewing/testing (https://github.com/theforeman/smart-proxy/pull/312 is blocking work on dhcp speedup).

Another approach would be to disable/change orchestration during fact import, but that's going to be messy. Dominic -- any thoughts on this?

OK, this code is completely new to me so bound to be things I was missing. Presumably you could make dhcp_update_required? return true if it's a new host ? I still don't see any point in hitting that code path unless you know something has changed.

It's possible to manually assign an ip address to an interface during host creation. It's also possible that ip suggested by foreman has been assigned by dhcpd before the host was saved. TIp conflict check makes sense for either of these cases.

Can you give me an idea of what patch you might accept here ? I personally don't believe that the current behaviour will scale whatever you might do to optimise the proxy code, and I don't think that you need to check the proxy during every fact import. If I was to submit a patch to :

1. Make dhcp_conflict_detected? return false unless a dhcp update is required as per the code above
2. Change dhcp_update_required? to return true if it's a new host creation

Would that patch be acceptable ? I'd rather not have to maintain our own fork, but this is currently totally useless for us as it causes puppet timeouts across our whole estate.

I think it's the other way around -- fact import is the case that needs "special" treatment. I don't think you can trigger this check using heuristics based on the record lifecycle without affecting host creation. It might be possible to set some flag indicating that fact import is in progress, but it's going to be messy.

I think the best place to start is to solve dhcp-related performance issues on smart-proxy, probably by replacing lease file parsing to omapi calls. As I said before, it's something I'll start working on once https://github.com/theforeman/smart-proxy/pull/312 is merged.

I'll create a separate issue in Foreman for you, perhaps the devs there will have another solution.

Hi Folks ,

do you think this is possible to workaround, mittigate somehow?

VM

There's probably stuff I've missed, but our workaround is to add this into dhcp_conflict_detected? :

return false unless dhcp? and dhcp_update_required?

and then to change dhcp_update_required? to :

def dhcp_update_required?
    return unless (build? or old)
    # IP Address / name changed, or 'rebuild' action is triggered and DHCP record on the smart proxy is not present/identical.
    return true if ((old.ip != ip) or (old.hostname != hostname) or (old.mac != mac) or (old.subnet != subnet) or
                    (!old.build? and build? and !dhcp_record.valid?))
    # Handle jumpstart
    #TODO, abstract this way once interfaces are fully used
    if self.is_a?(Host::Base) and jumpstart?
      if !old.build? or (old.medium != medium or old.arch != arch) or
          (os and old.os and (old.os.name != os.name or old.os != os))
        return true
      end
    end
    false
  end

We've not done exhaustive testing yet, but this seems to work.

we are hit by the same issue. its propably related to bug #12359 as well. i'll try to implement the workaround mentioned by matt.

Toni Schmidbauer wrote:

we are hit by the same issue. its propably related to bug #12359 as well. i'll try to implement the workaround mentioned by matt.

@Alexander Romanov mentioned this workaround has "some strange issues" @Toni Schmidbauer how does this look on your end?

meaning comment '#28' not issue 28

The false positive "ip already in use" during deploy is occuring only ocasionaly , i will post here if i will figure out an exact reproduction scenario.

This "ip already in use" clearly not related to this bug and/or fix.
That's another issues related to our particular installation.

until now we didn't try the patch mentioned above. will try to patch our foreman installation tomorrow.

after the patch when trying to deploy BareMetal

NoMethodError
undefined method `ip' for nil:NilClass
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:109:in `dhcp_update_required?'
/usr/share/foreman/app/models/concerns/orchestration/dhcp.rb:151:in `dhcp_conflict_detected?'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:464:in `_run__1228633995078718928__validation__480985469740422524__callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:405:in `__run_callback'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:385:in `_run_validation_callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:81:in `run_callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activemodel-3.2.21/lib/active_model/validations/callbacks.rb:53:in `run_validations!'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activemodel-3.2.21/lib/active_model/validations.rb:195:in `valid?'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/validations.rb:69:in `valid?'
/usr/share/foreman/app/models/concerns/orchestration.rb:59:in `valid?'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/autosave_association.rb:300:in `association_valid?'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/autosave_association.rb:289:in `block in validate_collection_association'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/autosave_association.rb:289:in `each'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/autosave_association.rb:289:in `validate_collection_association'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/autosave_association.rb:217:in `block in add_autosave_association_callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/autosave_association.rb:161:in `instance_eval'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/autosave_association.rb:161:in `block in define_non_cyclic_method'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:550:in `_run__4207259453130362107__validate__480985469740422524__callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:405:in `__run_callback'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:385:in `_run_validate_callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:81:in `run_callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activemodel-3.2.21/lib/active_model/validations.rb:228:in `run_validations!'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activemodel-3.2.21/lib/active_model/validations/callbacks.rb:53:in `block in run_validations!'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:469:in `_run__4207259453130362107__validation__480985469740422524__callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:405:in `__run_callback'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:385:in `_run_validation_callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:81:in `run_callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activemodel-3.2.21/lib/active_model/validations/callbacks.rb:53:in `run_validations!'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activemodel-3.2.21/lib/active_model/validations.rb:195:in `valid?'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/validations.rb:69:in `valid?'
/usr/share/foreman/app/models/concerns/orchestration.rb:59:in `valid?'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/validations.rb:77:in `perform_validations'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/validations.rb:50:in `save'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/attribute_methods/dirty.rb:22:in `save'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/transactions.rb:259:in `block (2 levels) in save'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/transactions.rb:313:in `block in with_transaction_returning_status'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/connection_adapters/abstract/database_statements.rb:192:in `transaction'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/transactions.rb:208:in `transaction'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/transactions.rb:311:in `with_transaction_returning_status'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/transactions.rb:259:in `block in save'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/transactions.rb:270:in `rollback_active_record_state!'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/transactions.rb:258:in `save'
/usr/share/foreman/app/models/concerns/foreman/sti.rb:29:in `save_with_type'
/usr/share/foreman/app/controllers/hosts_controller.rb:84:in `create'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/abstract_controller/base.rb:167:in `process_action'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_controller/metal/rendering.rb:10:in `process_action'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/abstract_controller/callbacks.rb:18:in `block in process_action'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:627:in `block (4 levels) in run_3859093308087087230__process_action__3397865074571343063__callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:215:in `block in conditional_callback_around_7773'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:326:in `around'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:310:in `_callback_around_3031'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_7773'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:626:in `block (3 levels) in _run_3859093308087087230__process_action__3397865074571343063__callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:215:in `block in conditional_callback_around_7772'
/usr/share/foreman/app/controllers/concerns/application_shared.rb:13:in `set_timezone'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_7772'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:625:in `block (2 levels) in _run_3859093308087087230__process_action__3397865074571343063__callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:215:in `block in conditional_callback_around_7771'
/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_7771'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:448:in `block in _run_3859093308087087230__process_action__3397865074571343063__callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:215:in `block in conditional_callback_around_7770'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:326:in `around'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:310:in `_callback_around_13'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_7770'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:414:in `_run_3859093308087087230__process_action__3397865074571343063__callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:405:in `__run_callback'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:385:in `_run_process_action_callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:81:in `run_callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/abstract_controller/callbacks.rb:17:in `process_action'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_controller/metal/rescue.rb:29:in `process_action'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_controller/metal/instrumentation.rb:30:in `block in process_action'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/notifications.rb:123:in `block in instrument'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/notifications.rb:123:in `instrument'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_controller/metal/instrumentation.rb:29:in `process_action'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_controller/metal/params_wrapper.rb:207:in `process_action'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/abstract_controller/base.rb:121:in `process'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/abstract_controller/rendering.rb:45:in `process'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_controller/metal.rb:203:in `dispatch'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_controller/metal.rb:246:in `block in action'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/routing/route_set.rb:73:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/routing/route_set.rb:73:in `dispatch'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/routing/route_set.rb:36:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/journey-1.0.4/lib/journey/router.rb:68:in `block in call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/journey-1.0.4/lib/journey/router.rb:56:in `each'
/usr/share/foreman/vendor/ruby/1.9.1/gems/journey-1.0.4/lib/journey/router.rb:56:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/routing/route_set.rb:608:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/apipie-rails-0.2.6/lib/apipie/extractor/recorder.rb:97:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/apipie-rails-0.2.6/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-1.4.7/lib/rack/etag.rb:23:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-1.4.7/lib/rack/conditionalget.rb:35:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/middleware/head.rb:14:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/middleware/params_parser.rb:21:in `call'
/usr/share/foreman/lib/middleware/catch_json_parse_errors.rb:9:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/middleware/flash.rb:242:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-1.4.7/lib/rack/session/abstract/id.rb:210:in `context'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-1.4.7/lib/rack/session/abstract/id.rb:205:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/middleware/cookies.rb:341:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/query_cache.rb:64:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activerecord-3.2.21/lib/active_record/connection_adapters/abstract/connection_pool.rb:479:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:405:in `_run__3413703529047677478__call__480985469740422524__callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:405:in `__run_callback'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:385:in `_run_call_callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/callbacks.rb:81:in `run_callbacks'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/railties-3.2.21/lib/rails/rack/logger.rb:32:in `call_app'
/usr/share/foreman/vendor/ruby/1.9.1/gems/railties-3.2.21/lib/rails/rack/logger.rb:18:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/middleware/request_id.rb:22:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-1.4.7/lib/rack/methodoverride.rb:21:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-1.4.7/lib/rack/runtime.rb:17:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/activesupport-3.2.21/lib/active_support/cache/strategy/local_cache.rb:72:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-1.4.7/lib/rack/lock.rb:15:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/actionpack-3.2.21/lib/action_dispatch/middleware/static.rb:83:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:136:in `forward'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:143:in `pass'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:155:in `invalidate'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:71:in `call!'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:51:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/railties-3.2.21/lib/rails/engine.rb:484:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/railties-3.2.21/lib/rails/application.rb:231:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/railties-3.2.21/lib/rails/railtie/configurable.rb:30:in `method_missing'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-1.4.7/lib/rack/builder.rb:134:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-1.4.7/lib/rack/urlmap.rb:64:in `block in call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-1.4.7/lib/rack/urlmap.rb:49:in `each'
/usr/share/foreman/vendor/ruby/1.9.1/gems/rack-1.4.7/lib/rack/urlmap.rb:49:in `call'
/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:77:in `process_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:142:in `accept_and_process_next_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:110:in `main_loop'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:448:in `block (3 levels) in start_threads'
/usr/share/foreman/vendor/ruby/1.9.1/gems/logging-2.0.0/lib/logging/diagnostic_context.rb:448:in `call'
/usr/share/foreman/vendor/ruby/1.9.1/gems/logging-2.0.0/lib/logging/diagnostic_context.rb:448:in `block in create_with_logging_context'

example of request during this error

2015-12-21T20:56:52 [app] [I] Completed 200 OK in 305.5ms (Views: 1.0ms | ActiveRecord: 12.2ms)
2015-12-21T20:56:55 [app] [I] Started POST "/hosts" for 46.227.11.53 at 2015-12-21 20:56:55 +0000
2015-12-21T20:56:55 [app] [I] Processing by HostsController#create as */*
2015-12-21T20:56:55 [app] [I] Parameters: {"utf8"=>"✓", "authenticity_token"=>"C7pLZ8ITB+oO4fQ7kzYDXZ5wesNi/1KAnErNbNETbVU=", "host"=>{"name"=>"test-bm", "hostgroup_id"=>"11", "compute_resource_id"=>"", "compute_profile_id"=>"3", "environment_id"=>"1", "puppet_ca_proxy_id"=>"1", "puppet_proxy_id"=>"1", "puppetclass_ids"=>[""], "managed"=>"true", "progress_report_id"=>"[FILTERED]", "type"=>"Host::Managed", "interfaces_attributes"=>{"0"=>{"_destroy"=>"0", "type"=>"Nic::Managed", "mac"=>"11:11:11:11:11:11", "identifier"=>"", "name"=>"test-bm", "domain_id"=>"1", "subnet_id"=>"1", "ip"=>"10.0.10.178", "managed"=>"1", "primary"=>"1", "provision"=>"1", "virtual"=>"0", "tag"=>"", "attached_to"=>""}}, "architecture_id"=>"1", "operatingsystem_id"=>"16", "provision_method"=>"build", "build"=>"1", "medium_id"=>"1", "ptable_id"=>"56", "disk"=>"", "root_pass"=>"[FILTERED]", "is_owned_by"=>"7-Users", "enabled"=>"1", "model_id"=>"", "comment"=>"", "overwrite"=>"false"}}

+1 for this. I've run into problems trying to use the DHCP proxy at scale. 125 subnets and hundreds of hosts, in our first datacenter, causes very long delays while enumerating the leases file. As a workaround, I'm thinking about disabling the DHCP proxy entirely, and handling management of our host reservations through puppet+dhcpd.conf. I posted more detail to google groups here:

https://groups.google.com/forum/#!topic/foreman-users/G2ivILPA42Q

setting ignore_puppet_facts_for_provisioning to true resolved this issue for us.

I opened a pull request (https://github.com/theforeman/smart-proxy/pull/409) that eliminates parsing of the dhcpd leases file on every request. The changes have been tested against a fairly low-load dhcpd server, and I would appreciate if you could run a test against a busy dhcpd server and report your findings here.

Correction: please submit your findings in the main ticket: http://projects.theforeman.org/issues/2687