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

@@ -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
+}

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
 

examples/mime.yaml

@@ -0,0 +1,3 @@
+--- 
+.jpeg: image/jpeg
+.png: image/test

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
     
     

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
+
+

lib/mongrel/handlers.rb

@@ -5,12 +5,35 @@ 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
+
+
   # The server normally returns a 404 response if an unknown URI is requested, but it
   # also returns a lame empty message.  This lets you do a 404 response
   # with a custom message for special URIs.

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

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'
+require 'mongrel/debug'
 
-$mongrel = {:host => "0.0.0.0", :port => 3000, :mime => nil, :server => nil, :docroot => "public", :tracing => false}
+$mongrel = RailsConfigurator.new :host => "localhost", :port => 3000, :environment => "development", :docroot => "public"
 
-
-# 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
-
-    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
+def self.mongrel
+  return $mongrel
 end
 
-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
-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__)

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

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