Making Rails Logs More Useful

2007-11-07 19:00:00 -0500


Here at Zetetic we do a lot of logging, and a lot of looking at logs. In particular, we have a couple of daemon processes implemented in Rails for PingMe that handle our message queueing and parsing of incoming messages (when you reply to your pings or create new ones by remote). If you have any experience with message queueing systems, you’ll recall that these are not easy things to maintain, and require access to really good diagnostics. And if you are familiar with Rails you’ll recall that there are no time-stamps prepended to the log messages, making it very difficult sometimes to track down what happened when.

I did a quick bit of poking around and came across this fantastic article with a number of tips in terms of logging. Their solution for the issue of formatting the messages (so that you can have timestamps) is to subclass Logger, and instantiate that.

However, we have our own Loggers all over the place, in our daemons, they use the Logger class which has been patched by Rails to have that timestamp-less format. What we do from there is replace the Rails logger instance with our own (there are a few reasons for this, having to do with forking processes, resources, and the nature of daemons that I don’t want to get into), which works beautifully:


logger = Logger.new("#{config[:log_dir]}/#{config[:name]}.log", 'daily')
unless config[:log_level].blank?
begin
logger.level = Logger.const_get(config[:log_level])
rescue StandardError => e
logger.level = Logger::INFO
logger.error "An exception occurred while setting log level to #{config[:log_level]}, setting to INFO. Exception: #{e.message}"
end
else
logger.level = Logger::INFO
end

logger.info "Initialized log @ #{Time.now.utc} with log_level #{logger.level.to_s}"
logger.info "Starting up Dispatcher #{config[:name]}..."

# over-ride the active record logger (which would be closed now)
ActiveRecord::Base.logger = logger
ActionMailer::Base.logger = logger

I really don’t feel like subclassing Logger, I just want to adjust the default behavior, since we’re using the same loggers everywhere. So I opened up config/environment.rb, and at the bottom of it, added this:


# re-patch logger to restore format patched out by Rails
class Logger
def format_message(severity, timestamp, program, message)
"#{timestamp.to_formatted_s(:db)} #{program}: [#{severity}] #{message}\n"
end
end

Works fantastic! Thanks to Maintainable Software for their post.


Social Networking with Rails using acts_as_network

2007-09-20 20:00:00 -0400

Update 25-APR-2008: This plugin has been updated for Rails 2.0. Update 06-JUN-2008: This plugin now includes acts_as_union, and we moved the repository to GitHub.

When we started integrating simple social networking features into PingMe we wanted to easily represent a bi-directional relationship between users in the system. When a user signs up for PingMe they can invite another user to join them. Once an invite is accepted, the users become mutual friends, or contacts in PingMe parlance, and can send Pings to each other.

Most importantly, we wanted the relationship to be bidirectional -when Jack is a friend of Jane then Jane should alsobe a friend of Jack.

Unfortunately we quickly realized that thismodel was not going to be so easy. The usual way of representing this type of network relationship using ActiveRecord is with an intermediate HABTM join, or with a self-referential has_many :through association. For example one might define a simple person model and then a join table tostore the friendship relation:

create_table :people, :force => true do |t|
  t.column :name, :string
end
  create_table :friends, {:id => false} do |t|
  t.column :person_id, :integer, :null => false
  t.column :person_id_friend, :integer, :null => false      # target of the relationship
end

The problem is that this model requires two rows in the intermediate table to make a relationship bi-directional.

jane = Person.create(:name => 'Jane')
jack = Person.create(:name => 'Jack')
jane.friends << jack
jane.friends.include?(jack)    =>  true   # Jack is Janes friend
jack.friends.include?(jane)    =>  false  # Jane is NOT Jack's friend

In short, you must explicitly define the reverse relation in order for this to work.

jack.friends << jane
jack.friends.include?(jane)    =>  true  # now they're buds

This can be implemented in a fairly DRY way using association callbacks as documented in Rails Recipes, but things start to get ugly when you want to express the relationship through a "proper" join model (like for an Invite) using has_many :through.

create_table :invites do |t|
  t.column :person_id, :integer, :null => false           # source of the relationship
  t.column :person_id_friend, :integer, :null => false    #  target of the relationship
  t.column :code, :string                                 # random invitation code
  t.column :message, :text                                # invitation message
  t.column :is_accepted, :boolean
  t.column :accepted_at, :timestamp                       # when did they accept?
end

In this case creating a reverse relationship is much more complex and could require the duplication of multiple values, making the data model decidedly non-DRY.

Enter acts_as_network

acts_as_network is a plugin that we developed for PingMe to resolve some of these issues. It drives the social networking features of the site. It'sintended to simplify the definition and storage of reciprocal relationships between entities using ActiveRecord by exposing a "network" of 2-wayconnections.

What makes it special is that it does this in a DRY way using only a single record in an intermediate has_and_belongs_to_many join table or has_many :through join model. There is no redundancy, and you need only one instance of an association or join model to represent both directions of the relationship. Consider this more desirable implementation:

class Invite <ActiveRecord>::Base
  belongs_to :person                    # the source of the invite
  belongs_to :person_target,            # the target of the invite
  :class_name => 'Person',
  :foreign_key => 'person_id_target'
end

class Person <ActiveRecord>::Base
  acts_as_network :friends, :through => :invites, :conditions => ["is_accepted = ?", true]
end

In this case acts_as_network implicitly defines five new properties on the Person model

person.invites_out        # has_many invites originating from me to others
person.invites_in         # has_many invites originating from others to me
person.friends_out        # has_many friends :through outbound accepted invites from me to others
person.friends_in         # has_many friends :through inbound accepted invites from others to me
person.friends            # the union of the two friend sets
- all people who I have invited all the people who have invited me and
Now...
# Jane invites Jack to be friends
invite = Invite.create(:person => jane, :person_target => jack, :message => "let's be friends!")
jane.friends.include?(jack)    =>  false   # Jack is not yet Jane's friend
jack.friends.include?(jane)    =>  false   # Jane is not yet Jack's friend either

invite.is_accepted = true  # Now Jack accepts the invite
invite.save and jane.reload and jack.reload

jane.friends.include?(jack)    =>  true   # Jack is Janes friend now
jack.friends.include?(jane)    =>  true   # Jane is also Jacks friend

So much cleaner!

Most of this magic is actually accomplished with a UnionCollection class that provides useful application-space functionalityfor emulating set unions across ActiveRecord collections. Once initialized, the UnionCollection itself will act as an array containing all of the records from each of its member sets, but its more interesting feature is that it will intelligently forward ActiveRecord method calls likefind, find_all_by_*, etc. to its member sets.

Check it out

Further documentation is available online, and you can easily install acts_as_network as a plugin to try it out:

% script/plugin install git://github.com/sjlombardo/acts_as_network.git
% rake doc:plugins

Please check it out and let us know what you think.

Zetetic is the creator of the super-flexible Tempo Time Tracking system.

Get The Belt!

2007-09-11 20:00:00 -0400


Blue Railsrumble

Update 2007-10-05: voting for the rumble is closed. We didn’t win, but we had a lot of fun participating. Thanks very much to those of you who took the time to vote for us, and for throwing us some feedback, we really appreciated it!

Whew, what a weekend! We signed up for the Rails Rumble a couple of weeks ago and competed this past weekend with quite a few other folks to put together an entire Rails web application from start to finish in 48 hours. We made our final adjustments just minutes before the SVN repository was closed to any new changes; it was a bit hairy just before midnight as everyone was checking in their code and the SVN server sloooooowed down.

We’ve been really busy with PingMe over the last few weeks, so we saw the Rumble as our chance to crank out most of the code for our next big project, TagTime (and we really want that belt!). Like PingMe, TagTime solves a particular need for us as a consultancy — a time entry system that gives us extremely flexible reporting for billing, streamlining how we bill our customers and helping us to quickly get metrics we can use to make informed decisions and estimate future growth. At the end of the month we don’t want to be hacking Excel spreadsheets exported from Product X to massage them into the views we actually want. We’ve tried a lot of other apps out there that came close but none of them have quite got it right. With TagTime it’s very easy to look up, for instance, how many hours two folks on a team billed for a particular group of tags, like ‘Company X’, ‘oracle’, ‘support’ for a range of dates, or maybe last month.

From there we can do RSS feeds of the data, Excel exports, invoice printing, etc. The version of TagTime up on the Rumble site doesn’t have the export functionalities in it yet, but we did manage to get the RSS feeds in there before the Rumble closed.

Cranking out so much code in such a short amount of time could have been quite a mess, but we had a lot of success following an iterative battle plan we had drawn up before hand. Our basic approach was for one of us to handle server setup while the other began coding the models, unit tests, and building fixture data that we could work with immediately. Once we were really hammering away at the app, the creation of the fixture data early on helped us immensely (although I’d be lying if I said we stuck with testing every bit of code until the end, there just wasn’t enough time!) Careful planning and solid execution is the Zetetic method, and it served us well.

One key feature that we didn’t get to implement during the Rumble was graphing — TagTime will provide illustrative graphs for date ranges, and we’ll use some means and averages to generates graphs to help predict what our billing might be in the upcoming cycle.

All in all, we’re very happy with how it came out and we’re ready to start using it for our own billing. Everyone else will have to wait a bit while we do just a little more work to get it ready for a proper launch. In the meantime you can check out TagTime yourself over here on the Rumble site, where you can vote for us if you are so inclined. Voting for the Rails Rumble is open to anybody, so if you have a spare minute and you like our products we could really use your vote. The winners will be announced at the end of this month at the Ruby East conference, and we’ll be there, too, if you want to say hello.


Lost In Translation!

2007-08-27 20:00:00 -0400


Last night we saw a really big surge in Japanese users on PingMe. Irashaimasen! We wondered what was up and saw that this article on a Japanese website might have been the cause.

We were really curious to find out what the article says so we popped it into Google Translate, but their Japanese support is still a little wonky. Can anyone help us out? Is it a decent review?


Mobile Mashup - Create scheduled reminders with your voice using Jott and PingMe

2007-08-19 20:00:00 -0400


How would you like to be able to “call in” a PingMe reminder over the phone?

Mike, a PingMe user, writes on his MyTechTalk blog

I think the folks at Jott and the folks at PingMe should join forces to create a stellar service. Jott’s voice to email technology could be modified by PingMe to quickly create reminders when I’m driving in my car and not in front of my computer.

Basically, Jott is a really useful mobile transcription service offering “mobile note taking and hands-free messaging”. Sign up and you can call their 800 number and speak a message that will be converted to written text and sent out by email. PingMe is a mobile service that sends out scheduled reminders to your cell phone and email on a defined schedule. Together, they are unstoppable.

We agreed it would be amazingly useful to phone in Pings while driving or just to save our fingers from typing an SMS message. Thus, we spent a little time coding up the back-end, and the PingMe / Jott mashup was born!

Start by going to http://www.jott.com to sign up. Do it now, don’t wait, because their service rocks. Follow the instructions on their site to activate your account. Then go into the contacts tab and add your PingMe address. (you can find your PingMe address in the welcome email we sent you, or on your profile page in PingMe).

We suggest you call the contact “GoPingMe”, so it’s sufficiently different than the default “Me” moniker that Jott uses for “note to self” type messages.

Then comes the fun part. Add Jott’s toll free number to your speed dial. Call up the Jott number. They say..

Who’d you want to Jott?

You say…

GoPingMe

They say…

BEEP

You speak…

Two days, hour eight, call and wish mom a happy birthday

Wait a few minutes, and voila, you’ve got a brand new Ping that will be sent to your mobile phone and email targets in two days at eight o’clock AM.

IMPORTANT NOTE: Before trying to create a Ping using Jott you should check out our help entry on mobile creation that describes the way PingMe time codes work. It explains why you’d say “2 days, hour eight” instead of “09/01/07 at 8:00am”. You should also read our recent post on Using time codes to create Pings for even more details.

Let us know what you think!