Marty Andrews

artful code

Sunday, September 2, 2007

Logging in Ruby on Rails

Ruby on Rails has a bunch of built in configuration items that are related to logging. You can set them up in your environment.rb file, or any of the specific environment override files. Here's an example of that file with all of the attributes listed:

Rails::Initializer.run do |config|config.logger = Logger.newconfig.log_level = :debugconfig.log_path = "log/myfilename.log"config.whiny_nils = trueconfig.active_record.logger = Logger.newconfig.active_record.colorize_logging = falseconfig.action_controller.logger = Logger.newconfig.action_mailer.logger = Logger.newend

The logger attributes allow you to create a global logger, or a specific logger for the active record, action controller and action mailer framweworks. The log_level controls how much logging gets printed out (we'll see an example a bit later). log_path defines the location of your log file. whiny_nils gives you some more verbose output if you call a method on a nil object, and colorize_logging gives you colored output in your logs, which is useful if you're viewing them in a *nix terminal window.

As an example, I can create a Rails controller like this.

class SampleController < ApplicationControllerdef do_logginglogger.debug("what?")logger.info("done")logger.warn("uh oh")logger.error("bang!")logger.fatal("KABOOM")endend

When executing the do_logging method on this class in a newly created Rails application, the following output appears in the terminal window:

what?doneuh ohbang!KABOOM

I don't find this very useful, so I try configuring my Rails applications wth log4r instead. Here's an example of my setup in the development.rb file.

config.log_level = :debugLog4r::Logger.root.level = Log4r::DEBUGformatter = Log4r::PatternFormatter.new(:pattern => "[%5l] %d %30C - %m")Log4r::StderrOutputter.new('console', :formatter => formatter)Log4r::Logger.new('App').add('console')RAILS_DEFAULT_LOGGER = Log4r::Logger.new('App::Rails')

This has substituted the Rails logger with a Log4r logger instead. The pattern formatter has been configured to print out the log level, date, context (logger name) and a log message. I've created a top level logger call 'App', and another logger called 'Rails' which is a child of the 'App' logger. The call to Logger.new with the parameter 'App::Rails' hooked the two together by name. Log4r loggers write to their parents output as well as their own, so I don't need to create any more outputters. Finally, I set my newly created logger to be the default Rails logger. Running my controller again now produces this output:

[DEBUG] 2007-06-26 11:45:56              App::Rails - what?[ INFO] 2007-06-26 11:45:56              App::Rails - done[ WARN] 2007-06-26 11:45:56              App::Rails - uh oh[ERROR] 2007-06-26 11:45:56              App::Rails - bang![FATAL] 2007-06-26 11:45:56              App::Rails - KABOOM

That's much more useful now, however, I don't have any meaningful way of distinguishing log messages coming from the Rails framework to log messages coming from my code. Framework log messages will all have the context of 'App::Rails' too. I'd like to have a different context. I can now change my controller to be like this though.

require "log4r"class SampleController < ApplicationControllerdef initialize@@log = Log4r::Logger.new('App::SampleController')enddef do_logging@@log.debug("what?")@@log.info("done")@@log.warn("uh oh")@@log.error("bang!")@@log.fatal("KABOOM")endend

Making this change gets me the following output:

[DEBUG] 2007-06-26 11:45:56   App::SampleController - what?[ INFO] 2007-06-26 11:45:56   App::SampleController - done[ WARN] 2007-06-26 11:45:56   App::SampleController - uh oh[ERROR] 2007-06-26 11:45:56   App::SampleController - bang![FATAL] 2007-06-26 11:45:56   App::SampleController - KABOOM

Now I can easily tell apart my log messages from the Rails framework messages.

You may have noticed that the Log4r configuration I used in development mode only outputs to the console, and not to a file as happens by default. I find that much more useful, as I don't have to bother cleaning up development log files any more. One final Log4r trick that I use is in production mode is to use a different outputter that automatically creates a new log file every day and names the files according to date. My production.rb file looks like this:

config.log_level = :warnLog4r::Logger.root.level = Log4r::WARNformatter = Log4r::PatternFormatter.new(:pattern => "[%5l] %d %30C - %m")Log4r::DateFileOutputter.new('logfile', :dirname => "log", :formatter => formatter)Log4r::Logger.new('App').add('logfile')RAILS_DEFAULT_LOGGER = Log4r::Logger.new('App::Rails')

Those settings makes it easy to manage log files in production mode. Some people have reported possible errors when multiple mongrel processes try to roll a log file at the same time, and I haven't tested it in anger. Be careful that you test if you get into that situation. Otherwise, this setup has worked quite well for me.

Wednesday, August 15, 2007

Ruby articles in Builder AU

Steve has been invited to contribute regularly to the Ruby series of articles in Builder AU. His first article, "Kicking off with Ruby", has just been published. Stay tuned for more.

Saturday, July 7, 2007

Ruby Nuby Screencasts

The Melbourne Ruby Group recently ran a Ruby Nuby night where they got a bunch of different people to do five minute presentations on various aspects of Ruby and Rails. I went along and recorded all of the presentations as screencasts. You can see them all on the Cogent Consulting screencasts page.

If Ruby on Rails is something you think you want to get into, we're running an introductory Ruby on Rails workshop on July 21. You can find out the details of our innovative pricing model and bid for a spot via our Easy Access Training page.

Sunday, June 3, 2007

Total financial transparency

One of the principles of the Cogent Consulting manifesto is that all financial information, including all salary information, is totally open. Of course, that's not so hard to deal with when there's only one or two of you at similar levels. Now, we have eight people working with Cogent, and the model is still holding strong. Come pay day, we send out a single email that has everyone's details in it.

Using this model from day one has actually been quite liberating. Financial conversations that are commonly quite taboo in Australia are totally open amongst Cogent employees. When anyone joins Cogent now, this model is one of the key points that I make to them before they start. Any potential staff have to be completely comfortable with all other staff knowing their income details. If they're not, Cogent is probably not the place for them.

Having said all of this, current Cogent staff members are all employed on a contract basis. Their rates are determined by the clients they work for, not by Cogent itself. Steve and I have decided recently to hire a permanent staff member, and of course, the same rules must apply to them. We're trying to be creative about structuring a package that is appealing to the high quality people we want to attract, but also gets us some reward for the financial risk we're taking.

It remains to be seen whether this model will work or not, but its an experiment we absolutely want to partake in. Building a company some other way isn't acceptable to us.

Sunday, May 6, 2007

I don't think you're a dickhead. You're hired.

Last week I had lunch with someone who wanted to work under a contract arrangement through Cogent Consulting. You could notionally call the meeting an interview, but you'd be using the term loosely. You see, Steve had spent over a year working with them at a previous organisation. There was no technical information I could figure out from that meeting that was going to be more useful than the experience Steve had had working with them. That left me with one main task - to figure out whether the culture fit was ok.

About 45 minutes into lunch after we'd all been chatting about various topics, I turned to Steve and said "well - my dickhead-ometer hasn't gone off, so he's ok by me". And that was how our latest Cogent staff member joined us.

Friday, April 20, 2007

Aggregated blogs for Cogent Consulting

I've just finished putting together an aggregated blogs site for Cogent Consulting. It includes blog entries from all Cogent staff and associates. Its also the first Ruby app that I've written which has gone 'live'. The code was much simpler than I expected it to be. It's less than 50 lines of code, and about half of that is the declarations of all of the bloggers on the site.

Check out http://blogs.cogentconsulting.com.au/.

Friday, April 13, 2007

Changing static factories to a testable design.

One of the attendees of the recent design improvement workshop that I ran sent me a question today. I've taken the liberty of changing the code a bit to demonstrate the example, but the intent is basically the same.

When we did the design improvement workshop we discussed how static methods can be a code smell. I'm wondering if you think this holds true for static factories since I don't feel right about creating a new instance of a factory just to ask it for an object ?

For example, I would normally have a factory like this:

public class ThingFactory {public static Thing create() {// ...}}

So the calling code would look like this:

public class ThingProcessor {public void process() {Thing myThing = ThingFactory.create();// ...}}

I'm a little anxious about code that looks like this:

public class ThingProcessor {public void process() {Thing myThing = new ThingFactory().create();// ...}}

Since we create two object's and only one is kept.

The problem with static methods is that they make unit testing harder. You can't override them in a subclass, and you can't mock them out. So the implementation you've got is the only one that can be called. Here's how I would implement the factory from the example above:

public interface ThingFactory {public Thing create();}public class DefaultThingFactory implements ThingFactory {public Thing create() {// ...}}

Now that I have an interface, I've got a mechanism that allows me to mock a method call. A useful trick to use in conjunction with that is to allow the actual implementation to be used by default in production code. You can do that with a combination of constructors like this:

public class ThingProcessor {private final ThingFactory _factory;// This constructor lets you inject a mock for testing.public ThingProcessor(ThingFactory factory) {_factory = factory;}// This constructor can be used by production code that just wants the default factory.public ThingProcessor() {this(new DefaultThingFactory());}public void process() {Thing myThing = _factory.create();// ...}}

The second design is much easier to test, yet the API for users of the ThingProcessor is exactly the same.

Screencast - software complexity on agile projects

About a week ago, I did a presentation to the Melbourne XP Enthusiasts Group about software complexity. I recorded the presentation as a screencast. The audio is a recording of me presenting to the live audience, so it hasn't been created specifically for viewing on video. It is still quite watchable though.

If you're interested in seeing it, it is now available for viewing on the Cogent Consulting web site.

Wednesday, April 4, 2007

Why aren't you changing your desk layout?

It seems that almost every place I go and consult at, developers are stuck in cubes with corner desks. You've got to be kidding me people! You all seem to know that software is about collaboration. You even laugh at the antics of Dilbert and his cube farm life. Yet you don't seem to be doing anything about it.

When you go home tonight, grab yourself a phillips head screwdriver. Bring it in to work tomorrow and make some adjustments. If you have some draws on your desk, take them off. If you have a return, take that off too. Put the draws somewhere nearby so you can still use them, but not under your desk. Now, take your monitor out of the corner, and move it to the square part of your desk.

Those simple modifications should mean that you now have enough room at your desk for two people to sit side by side and work at the same machine. Try asking a colleague to come over and give you some feedback on a bit of work you've just done. If she makes a suggestion, slide the keyboard over and ask her to show you a quick example of what she means. Amazing isn't it! Who would've thought that for no cost at all, you could get such a quick and noticeable improvement in the way you collaborate with people at work.

Wednesday, March 28, 2007

Screencasts of Keynote presentations with Snapz Pro X

The Snapz Pro X FAQ suggests that you can't record Keynote presentations because they take over the whole screen, basically because it uses the hardware directly rather than going through the software layers. Trying to record a screencast of a keynote video results in a constant shot of the last screenshot before the presentation started.

It turns out there is a way to get this to work though. The Keynote preferences has an option under the Slideshow settings called "Allow Expose, Dashboard and others to use the screen". Ticking that box will solve the problem and let you record as per normal. It claims that performance may be affected as a result, but I didn't notice any difference on my MacBook Pro.

Friday, March 2, 2007

Technorati Blog Claim

This entry only exists in order to "claim my blog" on Technorati.Technorati Profile

Tuesday, February 27, 2007

March Design Improvement EAT Workshop

Places are filling up fast for the March Desgn Improvement workshop that I'm running under the Cogent Consulting Easy Access Training program on March 24th. If you're interested in attending, get your bids in quick.

Saturday, February 24, 2007

How many tests do you need?

The number of tests you need for your system depends on how complex it is. Obvious, right? The tricky part is knowing how to measure that. There are a couple of good mathematical definitions that can help.

The Cyclomatic Complexity of a method is the number of linearly independent paths through a program's source code. This means that the Cyclomatic Complexity of a method is the minimum number of unit tests needed to test every path in a method.

Take this piece of code as an example:

public static String getFormattedName(String givenName, String middleName, String surname) {if (givenName != null) {givenName = givenName.trim();} else {givenName = "";}if (middleName != null) {middleName = middleName.trim();} else {middleName = "";}if (surname != null) {surname = surname.trim();} else {surname = "";}return givenName + " " + middleName + " " + surname;}

Every method starts out with a default Cyclomatic Complexity of one. The complexity is then increased by one for every linearly independent path through that method. In this case, each if statement in the method represents an extra path. So the total Cyclomatic Complexity for the method is four.

In other words, if you were writing tests for this method, you should write at least four of them.

The NPath Complexity of a method is the number of acyclic execution paths through that method. This means that the NPath Complexity basically represents all of the combinations of paths possible through a method, and is an upper bound on the number of tests you need to write for a method.

Lets use the same example code again.

Every method starts out with a default NPath Complexity of one. The complexity is then increased by one for every nested conditional loop, and multiplied by two for every parallel conditional loop. In this case, the method starts out with a complexity of one. It is multiplied by two at the first if block, bringing it up to two. It is multiplied by two again at the second if block, bringing it up to four. It is multiplied by two yet again at the last if block, bringing it up to eight.

In other words, if you were writing tests for this method, you should write up to eight of them.

So the number of tests you need to write is:

Cyclomatic Complexity <= Number of Tests <= NPath Complexity

The hard part now is to try and calculate what your complexity is. Fortunately, Complexian can do that for you.

Tuesday, February 20, 2007

Mile high code

On a flight from Melbourne to Newcastle today, I built some support for cyclomatic complexity into Complexian. It's not exposed via the Ant task or the main method yet, but the internals is working fine. I was pretty satisfied with the results of 45 minutes worth of coding.

Kent Beck and Erich Gamma famously wrote JUnit together on a plane trip too. There's something about the confined space and lack of other options (like phones for example) that causes you to focus on the task at hand. I wonder how much value you could get out of sending some members of your team on random flights together purely so they could pair on some interesting code.

Do you have any mile high code that you've created?

Saturday, February 10, 2007

Complexian. Simian's little brother.

With a bit of moral support from Simon Harris, the author of Simian, I've put together a tool called Complexian. It measures NPath complexity in your Java code, and warns you if it gets too high. The internals have been born from the same seeds of design as Simian, so it runs blindingly fast.

The NPath complexity of your code is exactly the number of unit tests required to get complete coverage of it. Complexian exists to measure the NPath complexity of your code and to warn you when it gets too high. Keeping the number low means that you can cover many more of the paths through your system with unit tests. That can save valuable time and money as projects get bigger and go for longer periods of time.

You can use Checkstyle already to check NPath complexity, but here's a few reasons you might prefer to use Complexian.

  1. Its significantly faster. Complexian can check the 1.2 million shared lines of code in JDK1.5 in under 15 seconds.
  2. Output is ordered so you see the “worst” offenders more obviously.
  3. You get summary of the total system, and how offensive the violations are in relation to it.
  4. Checkstyle has an overflow bug in it, so you don’t get the real story. (we’ve submitted a patch though, so this will go away eventually).

The most important reason for me is that complexity is treated like a second class citizen when its bundled in with other checkstyle checks. Too many times have I seen either the specific check turned off, or checkstyle itself turned off because developers didn’t like some formatting rule. Its important enough to me that I want that decision to be much more obvious, and treated with more consideration. If producing a tool that deals with the issue directly helps to highlight it, then I'm happy with the outcome.

You can see more details about Complexian and download it from the resources section of this site. Please send any feedback you have to me.

Friday, February 9, 2007

Exception handling rules of thumb

  1. Put your try/catch block around the smallest set of code that you can.
  2. Catch the most specific exception that you can.
  3. Interestingly, most applications should have one place in the system that completely violates both of these rules. It's the last line of defence to protect your users from whatever horrible things try to escape from inside your code.

Tuesday, January 23, 2007

EAT Design Improvement

Steve and I ran our first EAT workshop last Saturday, and it went pretty well. As part of the feedback that we gathered from the course, we asked for people to indicate what other material they might be interested in seeing. One of the options we put forward was a design improvement course based on some material I've worked on recently with Simon Harris. As it turns out, that seems to be the most popular option.

Is anyone else interested in seeing a course like that? If demand is high enough, we'll put it together for next month.

Easy Acess Training. One Saturday. BYO laptop. Seats auctioned off. Bids start at $100.

Sunday, January 21, 2007

Why IntelliJ IDEA is a great IDE for Ruby on Rails

JetBrains have just released the first beta of their IntelliJ IDEA Ruby Plugin. I've been using builds from the source repository for a while, and its my favourite environment for building Ruby on Rails applications. The strange thing is, I don't use it because I think it makes IntelliJ a great Ruby environment. I use it because IntelliJ is already a great environment for building HTML and CSS. When I'm building Rails apps, the framework allows my code to be so lean that I actually find myself spending more time working on the presentation of the system.

IntelliJ has been a great environment for HTML and CSS for years now. Its certainly very familiar to me from my Java web app development experience. The release of this plugin makes it at least an adequate environment for Ruby development. If history is anything to go by, JetBrains may well turn it into something which makes me wish I was forced to write more Ruby code in a Rails app :-)

Friday, January 19, 2007

Pragmatic requirements duplication

Duplication in code is generally considered bad, because it violates the DRY principle. Probably the only commonly accepted exception to the rule is documented in Extreme Programming Explained by Kent Beck. He says that the one higher priority (than removing duplicate code) in simple design is to ensure that the system "must communicate everything you want to communicate". In other words, the readers of the code need to be able to understand what it is doing by reading it.

Requirements in the form of Use Cases are no different in this sense. The Use Cases should ideally have no duplication within them, but it is actually more important that the readers of the requirements understand what is being described within them. In other words, if putting some duplication in helps your readers better understand what is going on, that's a good thing.

The main difference between these cases is the skill of the reader. The people reading the code are (probably) trained in how to design and write it. The people reading the Use Cases however are probably not trained. In many projects, Use Cases have to be signed off by representatives of the business with no training or experience in them at all. In such cases, being pragmatic about duplicating some sections of requirements may be perfectly appropriate.

Oh - and by the way, Use Cases are not design. If you end up with duplicate code as a result of having duplicated requirements, beat your developers with a stick. They should know better.

Thursday, January 18, 2007

Giving your team an Elizabethan collar

If you have a pet dog or cat that has a nasty cut, you'll find that it will lick its wounds. The wound can actually take longer to heal, or can get infected, as a result. Of course, your pet doesn't know that, its just doing what its instincts tell it to. To solve the problem, you give them an Elizabethan collar. It lets them continue eating and drinking, but doesn't let them cause any more damage to the wound. In the meantime, you can apply some disinfectant and clean the wound right up so there's no more problem.

Sometimes you come across software teams in the same situation. They've got a wound in their software, and they're instinctively licking away at it in the hope that it will get better. It might change from a nasty cut into a puss-filled scab, but its often not improving.

You can solve the problem in exactly the same way. Give the team an Elizabethan collar that lets them keep going on with their daily lives, but keeps them away from that wound. You might need a layer of abstraction, a checkstyle rule, or a continuous build. Preferably something automated that keeps them from twisting around and gnawing on that nasty gash. In the meantime, step in and apply whatever disinfectant is required to clean up the problem. A spoonful of refactoring will often do the trick, but sometimes a full transplant is required.

Once the job is done, you've got a choice. Sometimes you will choose to keep the collar because the team have become accustomed to living with it, and it might come in handy one day. You might also be able to remove the collar to let the team see your efforts at first aid. In many cases, that patch of skin will now be boring and uninteresting, so they won't bother with it anymore. If you're lucky however, they might be interested in the process you went through, and will resist the urge to gnaw next time they get cut, coming to ask for help instead.

Leaving the asshole behind

Someone I know just quit their job because they refused to spend any more time working with an asshole manager. They had been at the company for many years, and would have been what I would consider a reasonably loyal employee. Ultimately, that turned out to be completely over powered by the pain felt in dealing with the asshole manager.

Working in an environment that has no assholes is a good goal to have, so I'm supportive of the decision. Loyalty to people is far more important in my mind than loyalty to organisations. Its nice to find a company that has beliefs in line with your own, but those beliefs only come about because of the people that created them. Find those people, and work with them, regardless of what company they happen to be in.

Sunday, January 7, 2007

Fixing a static method code smell

Static methods are a clue that a piece of code might not be conforming well to object oriented design principles. Its probably not as well designed as it could be, or as reusable as it could be. Most of all, its probably not as testable as it could be. The contents of the method often belong on one of the objects being worked on, and sometimes belong in a whole new object unto themselves.

The first clue for how to fix it is to look at the parameters being worked on in the method. If it is, then you can convert the method to an instance method on that object. IntelliJ IDEA has a refactoring option called "Convert To Instance Method...", which will ask you which parameter to move the method to. If you're not using IntelliJ IDEA, you can move the method to the appropriate Object, delete the parameter, and use this instead.

public class AccountFunctions {public static void withdraw(Long amountInCents, Account account) {// ...}}

becomes:

public class Account {public void withdraw(Long amountInCents) {// ...}}

The second clue for how to fix it is to look at the local variables being used in the method. It's possible that the contents of the method belongs on one of them instead of one of the parameters. Maybe a singleton object is being accessed in the method for example. In this case, the solution is similar to the first option, except that the parameters all still exist.

public class CartFunctions {public static void addItemToCart(Long itemId) {Cart cart = Cart.getInstance();List items = cart.getItems();items.add(itemId);}}

becomes:

public class Cart {public void addItem(Long itemId) {// ...}}

The third clue for how to fix it is to create a completely new class just for the static method. The parameters on the method become instance variables, and a constructor should be created that takes them as parameters. The method itself becomes an instance method on that class that uses the instance variables instead of having parameters to it.

public class DatabaseFunctions {public static String buildSelectStatement(String tableName, Collection columns,Collection conditions, Collection orderBys) {// ...}}

becomes:

public class Query {private String _tableName;private Collection _columns;private Collection _conditions;private Collection _orderBys;public Query(String tableName, Collection columns, Collection conditions, Collection orderBys) {}public String toSql() {// ...}}