Project

General

Profile

Bug #12392

100% cpu usage on foreman-proxy DHCP calls

Added by Matt Jarvis over 3 years ago. Updated about 2 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
-
Category:
DHCP
Target version:
-
Difficulty:
Triaged:
No
Bugzilla link:
Pull request:
Team Backlog:
Fixed in Releases:
Found in Releases:

Description

At least since 1.8, the cpu usage on the foreman-proxy has been increasing massively. We now see it using 100% of cpu time, although it does appear to still be running as it's logging stuff, it's extremely slow and we see timeouts communicating with it. This is using Bind and isc-dhcp-server, and strangely restarting all of the daemons and the proxy itself seems to fix it for a while. I've tried upgrading to the latest git code, and this doesn't make any difference.


Related issues

Related to Smart Proxy - Bug #12359: 100% cpu usage foreman-proxy after upgrade to 1.9Resolved2015-10-31
Related to Smart Proxy - Bug #2687: Performance issues with large ISC dataset (DHCP smart proxy)Closed2013-06-20
Related to Foreman - Bug #12425: Fact import triggers ip conflicts checks, which drives cpu utilization to 100% on smart-proxyClosed2015-11-09

History

#1 Updated by Dominic Cleal over 3 years ago

  • Related to Bug #12359: 100% cpu usage foreman-proxy after upgrade to 1.9 added

#2 Updated by Dominic Cleal over 3 years ago

  • Project changed from Foreman to Smart Proxy
  • Category deleted (Smart proxies)
  • Status changed from New to Need more information

Could you check the comment on #12359 and try the same debugging step that Lukas suggests there? It will help us narrow down the area of code affecting it.

Also, please say if you have any smart proxy plugins installed - either RPMs with a rubygem-smart_proxy* prefix, or Debian packages with a ruby-smart-proxy* prefix.

#3 Updated by Matt Jarvis over 3 years ago

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

#4 Updated by Matt Jarvis over 3 years ago

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

#5 Updated by Dominic Cleal over 3 years ago

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

#6 Updated by Matt Jarvis over 3 years ago

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

#7 Updated by Dominic Cleal over 3 years ago

  • Subject changed from 100% cpu usage on foreman-proxy to 100% cpu usage on foreman-proxy DHCP calls
  • Category set to DHCP
  • Status changed from Need more information to New

So it's DHCP-related, since Foreman's calling /dhcp/:network/:record there. I have been suspecting that Foreman might be validating DHCP records more than it used to, which would cause more requests to the smart proxy if true.

The performance improvements in 1.10 (ticket #11866) may help slightly. Since the threads are all performing debug logging there, try putting your log level up to INFO or WARN - it may reduce the amount of logging. If it is already, then we might need to optimise those debug statements so they only run when debug logging's enabled.

Lastly, I don't think the bind message is a problem.

#8 Updated by Dmitri Dolguikh over 3 years ago

  • Category deleted (DHCP)

Smart-proxy is responding to three simultaneous calls to add a dhcp record, which is an expensive operation (and would drive up cpu usage high) if the lease file is large and/or you have a high volume of 'add_record' calls.

Does this sound like your environment?

#9 Updated by Matt Jarvis over 3 years ago

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

#10 Updated by Matt Jarvis over 3 years ago

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

#11 Updated by Matt Jarvis over 3 years ago

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

#12 Updated by Matt Jarvis over 3 years ago

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

#13 Updated by Matt Jarvis over 3 years ago

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'

#14 Updated by Dominic Cleal over 3 years ago

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.

#15 Updated by Matt Jarvis over 3 years ago

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.

#16 Updated by Matt Jarvis over 3 years ago

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

#17 Updated by Dmitri Dolguikh over 3 years ago

  • Related to Bug #2687: Performance issues with large ISC dataset (DHCP smart proxy) added

#18 Updated by Matt Jarvis over 3 years ago

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 ?

#19 Updated by Dmitri Dolguikh over 3 years ago

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

#20 Updated by Matt Jarvis over 3 years ago

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.

#21 Updated by Dmitri Dolguikh over 3 years ago

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?

#22 Updated by Matt Jarvis over 3 years ago

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.

#23 Updated by Dmitri Dolguikh over 3 years ago

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.

#24 Updated by Matt Jarvis over 3 years ago

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.

#25 Updated by Dmitri Dolguikh over 3 years ago

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.

#26 Updated by Dmitri Dolguikh over 3 years ago

  • Related to Bug #12425: Fact import triggers ip conflicts checks, which drives cpu utilization to 100% on smart-proxy added

#27 Updated by Veaceslav Mindru over 3 years ago

Hi Folks ,

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

VM

#28 Updated by Matt Jarvis over 3 years ago

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.

#29 Updated by Toni Schmidbauer over 3 years ago

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.

#30 Updated by Veaceslav Mindru over 3 years ago

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?

#31 Updated by Veaceslav Mindru over 3 years ago

Veaceslav Mindru wrote:

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?

after attemp the fix susgested in #28 getting following false positive during VM provisioning.

#32 Updated by Veaceslav Mindru over 3 years ago

meaning comment '#28' not issue 28

#33 Updated by Veaceslav Mindru over 3 years ago

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.

#34 Updated by Alexandr Romanov over 3 years ago

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

#35 Updated by Toni Schmidbauer over 3 years ago

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

#36 Updated by Veaceslav Mindru over 3 years ago

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'

#37 Updated by Veaceslav Mindru over 3 years ago

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

#38 Updated by Kyle Flavin over 3 years ago

+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

#39 Updated by Toni Schmidbauer over 3 years ago

setting ignore_puppet_facts_for_provisioning to true resolved this issue for us.

#40 Updated by Dmitri Dolguikh about 3 years ago

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.

#41 Updated by Dmitri Dolguikh about 3 years ago

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

#42 Updated by Dominic Cleal almost 3 years ago

  • Category set to DHCP
  • Status changed from New to Feedback

The inotify-related changes have now been made in develop (nightly) for 1.13, which should drastically reduce the amount of re-parsing of config/lease files during smart proxy requests. I'm moving this ticket state to feedback as hopefully the next release will resolve this issue.

#43 Updated by Michael Moll about 2 years ago

  • Status changed from Feedback to Resolved

Also available in: Atom PDF