Java The Hutt

In my last post I covered how newbies could be tripped up with symbols and their usage within various hashes. Today I'm going to talk about issues related to tracking down errors when things go wrong. An advantage of rails that is touted by many is the time savings of "convention over configuration" and refers to XML configuration files in J2EE with the tagline "XML situps". Now I completely buy the value of convention over explicit configuration with the flexibility to override, it is certainly a time saver. Although I can say with 100% certainty that I've never spent a full day writing an XML configuration file of any sort, the same cannot be said with respect to debugging a runtime problem in rails. I have a few examples of battle scars in my short 3 month travels with RoR. Let's go through each one:

1) I had a action method in my controller that I'd made private by accident while refactoring. (For all you javaheads out there the way ruby works is that you define access modifiers on their own line and they act as sort of a toggle switch, meaning that when you declare private, all methods below are private until another access modifier is defined, i.e. public. For those of you that are wincing, I agree and don't like the convention myself but have now gotten used to it) At any rate, when I ran my functional test for the controller it was failing on my assertion for a redirect. The action that I'd accidentally made private performed a redirect. The test harness was informing me that an HTTP 200 (success) was being returned which puzzled me and led to me to an hour of checking my parameters, session variables, as well as the underlying model components that were part of the action. Of course in the end it turned out that I'd accidentally forgotten to put a public identifier back into my code while refactoring some private methods. Unfortunately the test harness gave me a bad error which wasted an hour to and hour and a half of my time. It should've given me a 404 error as it shouldn't have been able to find the action.

2) This one is related to my lack of ruby knowledge at the time but the error is that I had and 'include' and a 'require' inside application_helper. I was including a module as well as requiring the module, which is apparently a no-no. This code worked in .13.1. and didn't work in .14.x. The error message I received was nothing even remotely related to the actual issue.

3) In my app configuration file included in the general rails 'environment.rb' file I had a path specified that did not exist. Rails provided no error message on startup and I had to find it by adding my app code to a new app until it broke. How's that for some debugging situps?

4) My rails application wouldn't startup in production mode. The error messages were nonexistent in the rails log files and in the apache env. and only showed up in lighttpd as:

2005-11-27 10:51:04: (mod_fastcgi.c.2196) unexpected end-of-file (perhaps the fastcgi process died): pid: 8002 fcgi-fd: 9 remote-fd: 8 
2005-11-27 10:51:04: (mod_fastcgi.c.2958) child exited, pid: 8002 status: 1 
2005-11-27 10:51:04: (mod_fastcgi.c.3005) response not sent, request sent: 812 connection-fd: 8 fcgi-fd: 9 
2005-11-27 11:16:22: (mod_fastcgi.c.1532) connect failed: 9 Connection refused 61 0 /tmp/ruby-fastcgi.BB1C1FB6-5F76-11DA-83BB-000393B4C164-239-0000058F6C5C1CC0.socket-1

Turns out I had a syntax error in production.rb, an errant keystroke. Looking back now it's obvious to me to look there when it was just the production environment that was failing, but at the time you don't know the lay of the land all that well and where to look when trouble strikes. Logs are normally where you go but again I was failed by rails' lack of verbosity.

5) This time I was using rails' handy migration feature to make changes to my DB schema and migrate my data. Only it was failing with only the following error to guide me:

michael-kovacs-powerbook-g4:~/loanback_src/trunk mkovacs$ rake migrate
(in /Users/mkovacs/loanback_src/trunk)
rake aborted!
cannot convert nil into String

Well as it turns out I had commented out the RAILSENV value in 'enviroment.rb' so that it would grab the value from the shell environment variable and this was the error that rails gave when it couldn't find a value for RAILSENV. No clear error message, not even a line number or a stack trace,

Again, I think that there's some really great things in rails, specifically the ease of testing, the thought of end to end application development and the things that are needed to build, deploy, and advance your application, but there is certainly room for improvement on a few fronts and error messages from rails when something goes wrong is #1 in my book.

To that end I ended up modifying my installation of rails to be a little more verbose on startup. I haven't have time to go back and do a clean implementation that has flags for runtime options but the relevant code to look at is the rails Initializer class, and specifically the process method where the list of things to do on startup resides. I also added debugging information to where the DB connection gets obtained...

    def process
      set_load_path
      STDERR.print "setting connection adapters..."
      set_connection_adapters

      require_frameworks
      load_environment

      initialize_database
      initialize_logger
      initialize_framework_logging
      initialize_framework_views
      initialize_routing
      initialize_dependency_mechanism
      initialize_breakpoints
      initialize_whiny_nils
      
      initialize_framework_settings
      
      # Support for legacy configuration style where the environment
      # could overwrite anything set from the defaults/global through
      # the individual base class configurations.
      load_environment
      
      load_framework_info

      load_plugins
    end

    def initialize_database
      return unless configuration.frameworks.include?(:active_record)
      STDERR.print "\n\ninitializing database... " + configuration.database_configuration.inspect.to_s
      ActiveRecord::Base.configurations = configuration.database_configuration
      ActiveRecord::Base.establish_connection
    end

You could add debug messages to wherever you'd like to monitor the startup execution of whatever you're interested in.
This is all very quick and dirty stuff but it's saved my skin a few times since some of the earlier problems and I figure other newbies like myself would be intimidated to try and figure out where rails is doing all of its magic. Well the startup time magic appears to all happen in

 /usr/lib/ruby/gems/1.8/gems/rails-X.XX.X/lib/initializer.rb 

which is called from boot.rb in the config directory of your app. At some point I'm sure someone will add something that does what I did only in a clean manner instead of a crude hack or if not I may get around to writing it myself and submitting it.