From f4a5c938d461d9c5dc17f521c9efaaf352b931fa Mon Sep 17 00:00:00 2001 From: zedshaw Date: Sat, 25 Mar 2006 21:15:30 +0000 Subject: First crack at some advanced debugging features for mongrel and the console. git-svn-id: svn+ssh://rubyforge.org/var/svn/mongrel/trunk@121 19e92222-5c0b-0410-8929-a290d50e31e9 --- bin/mongrel_rails | 11 +- examples/builder.rb | 13 +- examples/mime.yaml | 3 + lib/mongrel.rb | 97 ++++++++++---- lib/mongrel/debug.rb | 144 +++++++++++++++++++++ lib/mongrel/handlers.rb | 23 ++++ lib/mongrel/rails.rb | 74 +++++++++++ .../mongrel_console/lib/mongrel_console/console.rb | 136 +------------------ test/test_configurator.rb | 59 +++++++++ test/test_debug.rb | 27 ++++ 10 files changed, 431 insertions(+), 156 deletions(-) create mode 100644 examples/mime.yaml create mode 100644 lib/mongrel/debug.rb create mode 100644 test/test_configurator.rb create mode 100644 test/test_debug.rb diff --git a/bin/mongrel_rails b/bin/mongrel_rails index 95d0970..f6e6e59 100644 --- a/bin/mongrel_rails +++ b/bin/mongrel_rails @@ -2,7 +2,6 @@ require 'rubygems' require 'yaml' require 'mongrel' - class Start < GemPlugin::Plugin "/commands" include Mongrel::Command::Base @@ -229,6 +228,16 @@ class Restart < GemPlugin::Plugin "/commands" end end + GemPlugin::Manager.instance.load "mongrel" => GemPlugin::INCLUDE, "rails" => GemPlugin::EXCLUDE + +require 'mongrel/debug' +ObjectTracker.configure +MongrelDbg.configure + Mongrel::Command::Registry.instance.run ARGV + +END { +Class.report_object_creations +} \ No newline at end of file diff --git a/examples/builder.rb b/examples/builder.rb index 0319377..5f0803a 100644 --- a/examples/builder.rb +++ b/examples/builder.rb @@ -1,11 +1,22 @@ require 'mongrel' +class TestPlugin < GemPlugin::Plugin "/handlers" + include Mongrel::HttpHandlerPlugin + + def process(request, response) + STDERR.puts "My options are: #{options.inspect}" + STDERR.puts "Request Was:" + STDERR.puts request.params.to_yaml + end +end + config = Mongrel::Configurator.new :host => "127.0.0.1" do load_plugins :includes => ["mongrel"], :excludes => ["rails"] daemonize :cwd => Dir.pwd, :log_file => "mongrel.log", :pid_file => "mongrel.pid" listener :port => 3000 do - uri "/app", :handler => Mongrel::DirHandler.new(".", load_mime_map("mime.yaml")) + uri "/app", :handler => plugin("/handlers/testplugin", :test => "that") + uri "/app", :handler => Mongrel::DirHandler.new(".") load_plugins :includes => ["mongrel", "rails"] end diff --git a/examples/mime.yaml b/examples/mime.yaml new file mode 100644 index 0000000..6e7bb04 --- /dev/null +++ b/examples/mime.yaml @@ -0,0 +1,3 @@ +--- +.jpeg: image/jpeg +.png: image/test diff --git a/lib/mongrel.rb b/lib/mongrel.rb index b501c26..cd94b9b 100644 --- a/lib/mongrel.rb +++ b/lib/mongrel.rb @@ -238,12 +238,19 @@ module Mongrel attr_reader :header attr_reader :status attr_writer :status + attr_reader :body_sent + attr_reader :header_sent + attr_reader :status_sent - def initialize(socket) + def initialize(socket, filter = nil) @socket = socket @body = StringIO.new @status = 404 @header = HeaderOut.new(StringIO.new) + @filter = filter + @body_sent = false + @header_sent = false + @status_sent = false end # Receives a block passing it the header and body for you to work with. @@ -257,27 +264,37 @@ module Mongrel end # Primarily used in exception handling to reset the response output in order to write - # an alternative response. + # an alternative response. It will abort with an exception if you have already + # sent the header or the body. This is pretty catastrophic actually. def reset - @header.out.rewind - @body.rewind + if @body_sent + raise "You ahve already sent the request body." + elsif @header_sent + raise "You have already sent the request headers." + else + @header.out.rewind + @body.rewind + end end def send_status status = "HTTP/1.1 #{@status} #{HTTP_STATUS_CODES[@status]}\r\nContent-Length: #{@body.length}\r\nConnection: close\r\n" @socket.write(status) + @status_sent = true end def send_header @header.out.rewind @socket.write(@header.out.read) @socket.write("\r\n") + @header_sent = true end def send_body @body.rewind # connection: close is also added to ensure that the client does not pipeline. @socket.write(@body.read) + @body_sent = true end # This takes whatever has been done to header and body and then writes it in the @@ -287,6 +304,10 @@ module Mongrel send_header send_body end + + def done + @status_sent && @header_sent && @body_sent + end end @@ -317,10 +338,13 @@ module Mongrel # join the thread that's processing incoming requests on the socket. # # The num_processors optional argument is the maximum number of concurrent - # processors to accept. The server will return a "503 Service Unavailable" - # message when this happens so that they know to come back. The timeout - # parameter is a sleep timeout that is placed between socket.accept calls - # in order to give the server a cheap throttle time. It defaults to 0 and + # processors to accept, anything over this is closed immediately to maintain + # server processing performance. This may seem mean but it is the most efficient + # way to deal with overload. Other schemes involve still parsing the client's request + # which defeats the point of an overload handling system. + # + # The timeout parameter is a sleep timeout (in hundredths of a second) that is placed between + # socket.accept calls in order to give the server a cheap throttle time. It defaults to 0 and # actually if it is 0 then the sleep is not done at all. def initialize(host, port, num_processors=(2**30-1), timeout=0) @socket = TCPServer.new(host, port) @@ -349,15 +373,20 @@ module Mongrel nread = parser.execute(params, data) if parser.finished? - script_name, path_info, handler = @classifier.resolve(params[Const::REQUEST_URI]) + script_name, path_info, handlers = @classifier.resolve(params[Const::REQUEST_URI]) - if handler + if handlers params[Const::PATH_INFO] = path_info params[Const::SCRIPT_NAME] = script_name - request = HttpRequest.new(params, data[nread ... data.length], client) + request = HttpRequest.new(params, data[nread ... data.length], client) response = HttpResponse.new(client) - handler.process(request, response) + + handlers.each do |handler| + handler.process(request, response) + break if response.done + end + else client.write(Const::ERROR_404_RESPONSE) end @@ -384,30 +413,44 @@ module Mongrel end end + # Used internally to kill off any worker threads that have taken too long + # to complete processing. Only called if there are too many processors + # currently servicing. + def reap_dead_workers(worker_list) + mark = Time.now + worker_list.each do |w| + if mark - w[:started_on] > 10 * @timeout + STDERR.puts "Thread #{w.inspect} is too old, killing." + w.raise(StopServer.new("Timed out thread.")) + end + end + end + + # Runs the thing. It returns the thread used so you can "join" it. You can also # access the HttpServer::acceptor attribute to get the thread later. def run - BasicSocket.do_not_reverse_lookup=true - + @acceptor = Thread.new do while true begin client = @socket.accept - - if @workers.list.length >= @num_processors - STDERR.puts "Server overloaded with #{@workers.list.length} active processors." - client.write(Const::ERROR_503_RESPONSE) + worker_list = @workers.list + if worker_list.length >= @num_processors + STDERR.puts "Server overloaded with #{worker_list.length} processors (#@num_processors max)." client.close + reap_dead_workers(worker_list) else thread = Thread.new do process_client(client) end + thread[:started_on] = Time.now thread.priority=1 @workers.add(thread) - sleep @timeout if @timeout > 0 + sleep @timeout/100 if @timeout > 0 end rescue StopServer STDERR.puts "Server stopped. Exiting." @@ -437,11 +480,19 @@ module Mongrel # found in the prefix of a request then your handler's HttpHandler::process method # is called. See Mongrel::URIClassifier#register for more information. def register(uri, handler) - @classifier.register(uri, handler) + script_name, path_info, handlers = @classifier.resolve(uri) + + if not handlers or (path_info and path_info != "/" and path_info.length == 0) + # new uri that is just longer + @classifier.register(uri, [handler]) + else + handlers << handler + end end - # Removes any handler registered at the given URI. See Mongrel::URIClassifier#unregister - # for more information. + # Removes any handlers registered at the given URI. See Mongrel::URIClassifier#unregister + # for more information. Remember this removes them *all* so the entire + # processing chain goes away. def unregister(uri) @classifier.unregister(uri) end @@ -636,7 +687,7 @@ module Mongrel # are merged with the defaults prior to passing them in. def plugin(name, options={}) ops = resolve_defaults(options) - GemPlugin::Manager.instance.create(plugin, ops) + GemPlugin::Manager.instance.create(name, ops) end diff --git a/lib/mongrel/debug.rb b/lib/mongrel/debug.rb new file mode 100644 index 0000000..8b2dd5c --- /dev/null +++ b/lib/mongrel/debug.rb @@ -0,0 +1,144 @@ +require 'logger' +require 'set' + + +$mongrel_debugging=true + +module MongrelDbg + SETTINGS = { :tracing => {}} + LOGGING = { } + + def MongrelDbg::configure(log_dir = "mongrel_debug") + Dir.mkdir(log_dir) if not File.exist?(log_dir) + @log_dir = log_dir + end + + + def MongrelDbg::trace(target, message) + if SETTINGS[:tracing][target] + LOGGING[target].log(Logger::DEBUG, message) + end + end + + def MongrelDbg::begin_trace(target) + SETTINGS[:tracing][target] = true + if not LOGGING[target] + LOGGING[target] = Logger.new(File.join(@log_dir, "#{target.to_s}.log")) + end + MongrelDbg::trace(target, "TRACING ON #{Time.now}") + end + + def MongrelDbg::end_trace(target) + SETTINGS[:tracing][target] = false + MongrelDbg::trace(target, "TRACING OFF #{Time.now}") + LOGGING[target].close + LOGGING[target] = nil + end +end + + +module ObjectTracker + @active_objects = nil + @live_object_tracking = false + + def ObjectTracker.configure + @active_objects = Set.new + ObjectSpace.each_object do |obj| + @active_objects << obj.object_id + end + srand @active_objects.object_id + @sample_thread = Thread.new do + loop do + sleep(rand(3) + (rand(100)/100.0)) + ObjectTracker.sample + end + end + @sample_thread.priority = 20 + end + + def ObjectTracker.start + @stopit = true + @live_object_tracking = true + @stopit = false + end + + def ObjectTracker.stop + @live_object_tracking = false + end + + def ObjectTracker.sample + ospace = Set.new + ObjectSpace.each_object do |obj| + ospace << obj.object_id + end + + dead_objects = @active_objects - ospace + new_objects = ospace - @active_objects + live_objects = ospace & @active_objects + + STDERR.puts "#{dead_objects.length},#{new_objects.length},#{live_objects.length}" + + @active_objects = live_objects + new_objects + end + +end + +class Class + alias_method :orig_new, :new + + @@count = 0 + @@stoppit = false + @@class_caller_count = Hash.new{|hash,key| hash[key] = Hash.new(0)} + + def new(*arg,&blk) + unless @@stoppit + @@stoppit = true + @@count += 1 + @@class_caller_count[self][caller[0]] += 1 + @@stoppit = false + end + orig_new(*arg,&blk) + end + + + def Class.report_object_creations + @@stoppit = true + puts "Number of objects created = #{@@count}" + + total = Hash.new(0) + + @@class_caller_count.each_key do |klass| + caller_count = @@class_caller_count[klass] + caller_count.each_value do |count| + total[klass] += count + end + end + + klass_list = total.keys.sort{|klass_a, klass_b| + a = total[klass_a] + b = total[klass_b] + if a != b + -1* (a <=> b) + else + klass_a.to_s <=> klass_b.to_s + end + } + klass_list.each do |klass| + puts "#{total[klass]}\t#{klass} objects created." + caller_count = @@class_caller_count[ klass] + caller_count.keys.sort_by{|call| -1*caller_count[call]}.each do |call| + puts "\t#{call}\tCreated #{caller_count[call]} #{klass} objects." + end + puts + end + end + + def Class.reset_object_creations + @@stopit = true + @@count = 0 + @@class_caller_count = Hash.new{|hash,key| hash[key] = Hash.new(0)} + @@stoppit = false + end +end + + diff --git a/lib/mongrel/handlers.rb b/lib/mongrel/handlers.rb index 609a252..7d817bb 100644 --- a/lib/mongrel/handlers.rb +++ b/lib/mongrel/handlers.rb @@ -5,9 +5,32 @@ module Mongrel # just the minimum necessary for you to handle a request and shoot back # a response. Look at the HttpRequest and HttpResponse objects for how # to use them. + # + # This is used for very simple handlers that don't require much to operate. + # More extensive plugins or those you intend to distribute as GemPlugins + # should be implemented using the HttpHandlerPlugin mixin. + # class HttpHandler + + def process(request, response) + end + end + + + # This is used when your handler is implemented as a GemPlugin. + # The plugin always takes an options hash which you can modify + # and then access later. They are stored by default for + # the process method later. + module HttpHandlerPlugin + attr_reader :options + + def initialize(options={}) + @options = options + end + def process(request, response) end + end diff --git a/lib/mongrel/rails.rb b/lib/mongrel/rails.rb index fb4e172..808d7d3 100644 --- a/lib/mongrel/rails.rb +++ b/lib/mongrel/rails.rb @@ -1,6 +1,62 @@ require 'mongrel' require 'cgi' +# Creates Rails specific configuration options for people to use +# instead of the base Configurator. +class RailsConfigurator < Mongrel::Configurator + + # Used instead of Mongrel::Configurator.uri to setup + # a rails application at a particular URI. Requires + # the following options: + # + # * :docroot => The public dir to serve from. + # * :environment => Rails environment to use. + # + # And understands the following optional settings: + # + # * :mime => A map of mime types. + # + # Because of how Rails is designed you can only have + # one installed per Ruby interpreter (talk to them + # about thread safety). This function will abort + # with an exception if called more than once. + def rails(location, options={}) + ops = resolve_defaults(options) + + # fix up some defaults + ops[:environment] ||= "development" + ops[:docroot] ||= "public" + ops[:mime] ||= {} + + if @rails_handler + raise "You can only register one RailsHandler for the whole Ruby interpreter. Complain to the ordained Rails core about thread safety." + end + + $orig_dollar_quote = $".clone + ENV['RAILS_ENV'] = ops[:environment] + require 'config/environment' + require 'dispatcher' + require 'mongrel/rails' + + @rails_handler = RailsHandler.new(ops[:docroot], ops[:mime]) + end + + + # Reloads rails. This isn't too reliable really, but + # should work for most minimal reload purposes. Only reliable + # way it so stop then start the process. + def reload! + if not @rails_handler + raise "Rails was not configured. Read the docs for RailsConfigurator." + end + + STDERR.puts "Reloading rails..." + @rails_handler.reload! + STDERR.puts "Done reloading rails." + + end +end + # Implements a handler that can run Rails and serve files out of the # Rails application's public directory. This lets you run your Rails # application with Mongrel during development and testing, then use it @@ -83,3 +139,21 @@ class RailsHandler < Mongrel::HttpHandler end end end + + +if $mongrel_debugging + + # Tweak the rails handler to allow for tracing + class RailsHandler + alias :real_process :process + + def process(request, response) + MongrelDbg::trace(:rails, "REQUEST #{Time.now}\n" + request.params.to_yaml) + + real_process(request, response) + + MongrelDbg::trace(:rails, "REQUEST #{Time.now}\n" + request.params.to_yaml) + end + end + +end diff --git a/projects/mongrel_console/lib/mongrel_console/console.rb b/projects/mongrel_console/lib/mongrel_console/console.rb index cefb610..1b2d674 100644 --- a/projects/mongrel_console/lib/mongrel_console/console.rb +++ b/projects/mongrel_console/lib/mongrel_console/console.rb @@ -6,134 +6,17 @@ rescue end require 'rubygems' require 'yaml' -require 'mongrel' +require 'mongrel/rails' require 'config/environment' require 'dispatcher' -require 'mongrel/rails' - -$mongrel = {:host => "0.0.0.0", :port => 3000, :mime => nil, :server => nil, :docroot => "public", :tracing => false} - - -# Tweak the rails handler to allow for tracing -class RailsHandler - alias :real_process :process - - def process(request, response) - if $mongrel[:tracing] - open("log/mongrel.log", "a+") do |f| - f.puts ">>>> REQUEST #{Time.now}" - f.write(request.params.to_yaml) - f.puts "" - end - end +require 'mongrel/debug' - real_process(request, response) - - if $mongrel[:tracing] - open("log/mongrel.log", "a+") do |f| - response.reset - f.puts ">>>> RESPONSE status=#{response.status} #{Time.now}" - f.write(response.header.out.read) - f.puts "" - end - end - end -end +$mongrel = RailsConfigurator.new :host => "localhost", :port => 3000, :environment => "development", :docroot => "public" -def load_mime_map(mime_map) - mime = {} - - # configure any requested mime map - if mime_map - puts "Loading additional MIME types from #{mime_map}" - mime.merge!(YAML.load_file(mime_map)) - - # check all the mime types to make sure they are the right format - mime.each {|k,v| puts "WARNING: MIME type #{k} must start with '.'" if k.index(".") != 0 } - end - - return mime -end - -# define a bunch of mongrel goodies -def self.start(options={}) - if $mongrel[:server] - STDERR.puts "Mongrel already running on #{$mongrel[:host]}:#{$mongrel[:port]}" - else - $mongrel.merge! options - - # need this later for safe reloading - $orig_dollar_quote = $".clone - - # configure the rails handler - rails = RailsHandler.new($mongrel[:docroot], load_mime_map($mongrel[:mime])) - - server = Mongrel::HttpServer.new($mongrel[:host], $mongrel[:port]) - server.register("/", rails) - $mongrel[:rails] = rails - - # start mongrel processing thread - server.run - STDERR.puts "Mongrel running in #{ENV['RAILS_ENV']} mode on #{$mongrel[:host]}:#{$mongrel[:port]}." - $mongrel[:server] = server - - nil - end -end - - -def self.stop - if $mongrel[:server] - $mongrel[:server].stop - $mongrel[:server] = nil - $mongrel[:rails] = nil - else - STDERR.puts "Mongrel not running." - end - nil +def self.mongrel + return $mongrel end -def self.restart - stop - start - nil -end - -def self.reload - if $mongrel[:rails] - STDERR.puts "Reloading rails..." - $mongrel[:rails].reload! - STDERR.puts "Done reloading rails." - else - STDERR.puts "Mongrel not running." - end - - nil -end - -def self.status - if $mongrel[:server] - STDERR.puts "Mongrel running with:" - $mongrel.each do |k,v| - STDERR.puts "* #{k}: \t#{v}" - end - else - STDERR.puts "Mongrel not running." - end - - nil -end - -def self.trace - $mongrel[:tracing] = !$mongrel[:tracing] - if $mongrel[:tracing] - STDERR.puts "Tracing mongrel requests and responses to log/mongrel.log" - else - STDERR.puts "Tracing is OFF." - end -end - - def tail(file="log/#{ENV['RAILS_ENV']}.log") STDERR.puts "Tailing #{file}. CTRL-C to stop it." @@ -159,15 +42,6 @@ def tail(file="log/#{ENV['RAILS_ENV']}.log") nil end - -GemPlugin::Manager.instance.load "mongrel" => GemPlugin::INCLUDE, "rails" => GemPlugin::EXCLUDE - -ENV['RAILS_ENV'] ||= 'development' -puts "Loading #{ENV['RAILS_ENV']} environment." - -# hook up any rails specific plugins -GemPlugin::Manager.instance.load "mongrel" => GemPlugin::INCLUDE - puts "Starting console. Mongrel Commands: start, stop, reload, restart, status, trace, tail" IRB.start(__FILE__) diff --git a/test/test_configurator.rb b/test/test_configurator.rb new file mode 100644 index 0000000..2fb9f85 --- /dev/null +++ b/test/test_configurator.rb @@ -0,0 +1,59 @@ +require 'test/unit' +require 'mongrel' + +$test_plugin_fired = 0 + +class TestPlugin < GemPlugin::Plugin "/handlers" + include Mongrel::HttpHandlerPlugin + + def process(request, response) + $test_plugin_fired += 1 + end +end + + +class Sentinel < GemPlugin::Plugin "/handlers" + include Mongrel::HttpHandlerPlugin + + def process(request, response) + raise "This Sentinel plugin shouldn't run." + end +end + + +class MongrelDbgTest < Test::Unit::TestCase + + def test_base_handler_config + config = Mongrel::Configurator.new :host => "localhost" do + listener :port => 3111 do + # 2 in front should run, but the sentinel shouldn't since dirhandler processes the request + uri "/", :handler => plugin("/handlers/testplugin") + uri "/", :handler => plugin("/handlers/testplugin") + uri "/", :handler => Mongrel::DirHandler.new(".", load_mime_map("examples/mime.yaml")) + uri "/", :handler => plugin("/handlers/sentinel") + + uri "/test", :handler => plugin("/handlers/testplugin") + uri "/test", :handler => plugin("/handlers/testplugin") + uri "/test", :handler => Mongrel::DirHandler.new(".", load_mime_map("examples/mime.yaml")) + uri "/test", :handler => plugin("/handlers/sentinel") + run + end + end + + res = Net::HTTP.get(URI.parse('http://localhost:3111/test')) + assert res != nil, "Didn't get a response" + assert $test_plugin_fired == 2, "Test filter plugin didn't run twice." + + + res = Net::HTTP.get(URI.parse('http://localhost:3111/')) + assert res != nil, "Didn't get a response" + assert $test_plugin_fired == 4, "Test filter plugin didn't run 4 times." + + config.stop + + assert_raise Errno::ECONNREFUSED do + res = Net::HTTP.get(URI.parse("http://localhost:3111/")) + end + end + +end diff --git a/test/test_debug.rb b/test/test_debug.rb new file mode 100644 index 0000000..7d0cb45 --- /dev/null +++ b/test/test_debug.rb @@ -0,0 +1,27 @@ +require 'test/unit' +require 'mongrel/rails' +require 'mongrel/debug' +require 'fileutils' + +class MongrelDbgTest < Test::Unit::TestCase + + def setup + FileUtils.rm_rf "mongrel_debug" + MongrelDbg::configure + end + + def test_tracing_to_log + MongrelDbg::begin_trace(:rails) + MongrelDbg::trace(:rails, "Good stuff") + MongrelDbg::end_trace(:rails) + + assert File.exist?("mongrel_debug"), "Didn't make logging directory" + assert File.exist?("mongrel_debug/rails.log"), "Didn't make the rails.log file" + assert File.size("mongrel_debug/rails.log") > 0, "Didn't write anything to the log." + + Class.report_object_creations + Class.reset_object_creations + Class.report_object_creations + end + +end -- cgit v1.2.3-24-ge0c7