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.

PingMe Updates - Default Confirmation and Targets

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


Last night we pushed a new version of PingMe out so now is a good time to mention some feature requests we’ve very happily implemented based on your feedback over the last few weeks.

In an update a couple of weeks ago we added two new flags you can provide while creating Pings by remote. This went out on our mailing list, but not here and it isn’t in the Help page yet, so I’d like to recap:

Specify the ‘c’ tag to turn Require Confirmation on or off on a Ping, like so:


1d h6p Call your mother c:y
-or-
1d h6p Call your mother c:n

You could also type out yes or no if you are so inclined. Going hand in hand with that addition a couple of weeks ago is the new Always Confirm Pings setting on the user profile that we rolled out last night. Many of you wanted to Require Confirmation to always be enabled on your pings (we did, too), so we added this flag to your profile to do just that:

That’s really handy for us, it means we don’t even have to use the new c: flag to enable Require Confirmation when we create pings by remote.

Last night’s update also included one more oft-requested feature that we also wanted to have, which makes creating pings on the web and remotely a bit quicker: default targets.

New users will find that the initial E-mail target we create for them is set to be a default. You can make any target one of your defaults by editing it in the sidebar and checking the Default? flag:

One last change we made was a stability update. A couple of PingMe users have made the mistake of setting their profile e-mail account in Jott to their PingMe address, rather than setting up a contact called PingMe. This can cause a pretty nasty mail loop, so we implemented some fixes and checks to prevent that from ever happening again.

If you are having any trouble receiving your pings, or sending pings from Jott, send an e-mail to support@zetetic.net and we’ll get you back on track.


PingMe - Two More Requested Features!

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


I almost forgot to mention in today’s earlier post that there are two more new features that many people have requested.

If you open up a ping, and click on the drop-down menu for repeat settings you’ll see two new ones, ‘Mon-Fri’ and ‘Bi-weekly’:

Mon-Fri pings don’t execute over the weekend. Now I won’t get my 7am “Wake up!” ping when I’m trying to sleep in, and that makes me very happy.

Bi-weekly pings are just that, they repeat every two weeks instead of every week, on the same day of the week as the initial date you set.

Login to PingMe now to start taking advantage of the work-week feature ;-)

Your feedback is driving PingMe’s development, so please keep these feature requests coming, and send them to support@gopingme.com. Some of them spur us on to implementing features we want for ourselves, while others are just awesome ideas that we can’t help but adopt.

Update:

You can also specify these new intervals when creating pings by remote. Use the value ‘f’ with the repeating flag to set a Mon-Fri ping, like this:


h 4pm hit the road before traffic gets bad r:f

Similarly, use the value ‘b’ for bi-weekly pings:


h9 m45 project status meeting r: b

Get The Belt!

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


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.