Thursday, August 21, 2014

Unobtrusive Logging with a Decorator

I've recently added logging to LightService. The organizers pipe log messages to whatever you define as your logger.

I, [LS] - calling organizer TestDoubles::MakesTeaAndCappuccino
I, [LS] - @keys in context: :tea, :milk, :coffee
I, [LS] - executing TestDoubles::MakesTeaWithMilkAction
I, [LS -   expects: :tea, :milk
I, [LS] -   promises: :milk_tea
I, [LS] -     keys in context: :tea, :milk, :coffee, :milk_tea
I, [LS] - executing TestDoubles::MakesLatteAction
I, [LS] -   expects: :coffee, :milk
I, [LS] -   promises: :latte
I, [LS] -     keys in context: :tea, :milk, :coffee, :milk_tea, :latte

This blog post tells you the story of how I added logging to this gem I maintain.

What do you think of this code?

class WithReducer
  attr_reader :context

  def with(data = {})
    @context = LightService::Context.make(data)
    self
  end

  def reduce(*actions)
    raise "No action(s) were provided" if actions.empty?
    actions.flatten!

    actions.reduce(context) do |context, action|
      action.execute(context)
    end
  end
end

It's not that hard to figure out what's going on in this object. It has 2 methods, #with and #reduce. The #with method is simple, it creates a Context object through the factory method and returns self for chaining. #reduce takes an arbitrary number of actions and reduces them by calling their #execute method.

Ok, let’s add logging around this:

class WithReducer
  attr_reader :context

  def with(data = {})
    logger.info("[LS] - calling organizer <#{organizer.to_s}>")

    @context = LightService::Context.make(data)

    logger.info("[LS] - keys in context: #{extract_keys(decorated.context.keys)}")

    self
  end

  def reduce(*actions)
    raise "No action(s) were provided" if actions.empty?
    actions.flatten!

    actions.reduce(context) do |context, action|
      result = action.execute(context)

      logger.info("[LS] - executing <#{action.to_s}>")
      if defined? action.expects and action.expects.any?
        logger.info("[LS] - expects: #{extract_keys(action.expects)}")
      end
      if defined? action.promises and action.promises.any?
        logger.info("[LS] - promises: #{extract_keys(action.promises)}")
      end
      logger.info("[LS] - keys in context: #{extract_keys(context.keys)}")

      result
    end
  end

  private

  def extract_keys(keys)
    keys.map {|key| ":#{key}" }.join(', ')
  end
end

This is the exact same core logic as the one in the first example, except it got polluted with logging. This code works, but seeing what the two instance methods do is not obvious, far from simple. What's wrong here? First, two separate concerns (logging and the core functionality) got squashed into one. Second, when the logging logic changes the underlying core logic will be touched violating the Single Responsibility Principle.

Logging and the core functionality of this code should be separated out. The logging needs to wrap around (decorate) the core functionality. It should look something like this:

A decorator - the WithReducerLogDecorator in this case - publishes the exact same interface as the object it decorates, it has the with and reduce methods. I started with those when I went about refactoring this:

class WithReducerLogDecorator
  def with(data = {})
  end

  def reduce(*actions)
  end
end

Then I "wrapped" the original logic with this decorator. The log decorator delegates the calls to the wrapped object, which is WithReducer in this case:

class WithReducerLogDecorator
  attr_reader :decorated

  def initialize(decorated = WithReducer.new)
    @decorated = decorated
  end

  def with(data = {})
    decorated.with(data)
  end

  def reduce(*actions)
    decorated.reduce(*actions)
  end
end

At this point it does not matter which WithReducer class I'd use. Using the original one or the decorated should produce the exact same functionality.
I started adding logging around the decorated methods, refactoring the #with method was first:

class WithReducerLogDecorator
  attr_reader :decorated, :organizer

  def initialize(decorated = WithReducer.new, organizer)
    @decorated, @organizer = decorated, organizer
  end

  def with(data = {})
    logger.info("[LS] - calling organizer <#{organizer.to_s}>")

    decorated.with(data)

    logger.info("[LS] - keys in context: #{extract_keys(decorated.context.keys)}")
    self
  end

  ...
end

Adding logging around the #reduce method was a bit harder. It reduces the provided actions by calling their execute method. There is no easy way to hook into that process just yet. However, calling the provided block within the reduce block opens up the routine for extension (Open/closed principle). I changed the original reduce method like this:

class WithReducer
  ...

  def reduce(*actions)
    raise "No action(s) were provided" if actions.empty?
    actions.flatten!

    actions.reduce(context) do |context, action|
      result = action.execute(context)
      # ::: Invoke the provided block :::
      yield(context, action) if block_given?
      result
    end
  end
end

The logging logic can now wrap around the #reduce method like this:

class WithReducerLogDecorator
  ...

  def reduce(*actions)
    decorated.reduce(*actions) do |context, action|
      # ::: All this code is executed within the decorated reduce block :::
      logger.info("[LS] - executing <#{action.to_s}>")
      if defined? action.expects and action.expects.any?
        logger.info("[LS] - expects: #{extract_keys(action.expects)}")
      end
      if defined? action.promises and action.promises.any?
        logger.info("[LS] - promises: #{extract_keys(action.promises)}")
      end
      logger.info("[LS] - keys in context: #{extract_keys(context.keys)}")
    end
  end

  private

  def extract_keys(keys)
    keys.map {|key| ":#{key}" }.join(', ')
  end
end

And with that I wrapped the original #with and #reduce methods with logging from outside with a decorator. I separated the two concerns: the core logic and the logging around it. I only need to touch the decorator object when the logging logic needs to be changed and I don't even need to look at the logging code when the core logic changes.

I learned about these concepts 9 years ago when I used Aspect Oriented Programming (AOP). I was fascinated by Around Advices, where logging was applied around a routine, beautifully separating the concerns.

Saturday, July 19, 2014

Use GitHub as Your Professional Portfolio

I've been doing quite a bit of candidate interviewing for the "Ruby Engineer - Remote" position we would like to fill. Our thought-out process starts with filtering out applicants based on their resume, their cover letter and their digital portfolio (website, blog or GitHub profile). I am surprised how many people have a GitHub account with no activity at all. I think that's wrong.

I took a look at my own GitHub profile. The activity looks pretty nice when I include the private projects.

However, when I looked at it as a non-authenticated user, the picture is not so stellar.

I would be happy to see candidates with as much public activity as I have. Do I contribute to open source software? Sometimes, not as often as I'd like. Then how do I have this much activity? Simple: I practice and I push everything I can to GitHub.

I want to advertise what languages I am playing with, what tools and frameworks I've been looking at. When I read books I create a quick and simple repository, I practice the examples by writing a failing test against them and when I reach the end of a chapter I commit and push the code to GitHub.

My GitHub profile is my own professional practicing-learning diary. I've recently started to look into Erlang and Clojure. Am I any good at these languages? No, or not yet! As I read books, learn new things and practice I'll sure get better. Last fall I looked at Erlang, and in November I switched to Clojure. By January I worked on the fizz-buzz kata and I got as far as playing with a Tic-Tac-Toe game in Clojure. Then I started to focus on my own gem, LightService and these days I am back at looking at Clojure.

As a professional, you've been learning a new language, you've been toying with the latest JavaScript MVC frameworks, why don't you broadcast that information? Don't let it sit on your computer! More and more companies will check your GitHub activity as you try to find a new job. They would be happy to see you're curious, you've been learning and you care about your own professional future.

Do yourself a favor and push as much of your learning to GitHub as possible. People - like me - looking at your profile there will jump on candidates who are "radiating that information". And it does not have to be GitHub, it can be BitBucket or anything else.

Just make sure whatever you do, it gets out there!

Wednesday, May 14, 2014

Expects and Promises in LightService

I received an issue a few weeks ago for the LightService project:

@adomokos, I saw an internal tool used at Github that is a lot like LightService. One nice they had was this notion of Promises and Expectations. Used the following way:

class FrothMilk
  include LightService::Action
  expects :milk, :cup
  promises :frothed_milk_in_cup

  executed {...}
end

You can immediately tell what this action expects from the context, and what this action promises to set in the context. An organizer would find this useful because it can see the chain of actions and check if they're compatible by looking at the expectations and promises.
What do you think? Would you like this included in LightService?

Oh wow! Github is using something similar to LightService? I'd like to see that! The concept of expects and promises sounded like a very good idea, I asked the person to submit a Pull Request for it. I found it pretty good when it arrived a few weeks later, but I wanted to polish it up a bit more.

This is how I had been writing actions with LightService:

class FooAction
  include LightService::Action

  executed do |context|
    baz = context.fetch :baz

    bar = baz + 2
    context[:bar] = bar
  end
end

When I look at this action - and many others I have written over the years - I notice a common pattern: I have to pull items from the context I want to work with, and I need to push the items I need to expose back into it. Although I try to keep actions small, doing this is repeated all over.

I prefer to call fetch when I pull an item from the context hash as the call throws a KeyError when the hash does not have the key I am asking for. Using the accessor baz = context[:baz] would force me dancing around nils in the code which I try to avoid.

The expects macro will help you no matter how you access the value in the hash as the LightService action will throw an ExpectedKeysNotInContextError if the key is not found in the context. The action expects the key to be in the context and when it's not provided, the call will blow up right there, no further processing will take place.

The action can be changed this way after the expects macro is introduced:

class FooAction
  include LightService::Action
  expects :baz

  executed do |context|
    baz = context.fetch :baz

    bar = baz + 2
    context[:bar] = bar
  end
end

Having the expects macro solved the problem of making sure the key is in the context before execution. However, I wanted to see if this macro could be used to generate accessors in the Context on the fly with the given key. This way I don't need to pull the items from the context one by one, I could just call this "magic" reader that fetches the value for me. With a bit of metaprogramming I was able to do just that. The action can be changed like this:

class FooAction
  include LightService::Action
  expects :baz

  executed do |context|
    # Notice how I use `context.baz` here
    bar = context.baz + 2
    context[:bar] = bar
  end
end

This is all great, but what about promising what the context hash will have after execution? The promises macro does that; when the promised key is not in the context, a PromisedKeysNotInContextError is thrown. This is how the action looks after using the promises keys:

class FooAction
  include LightService::Action
  expects :baz
  promises :bar

  executed do |context|
    # Notice how I use `context.baz` here
    bar = context.baz + 2
    context[:bar] = bar
  end
end

Setting the value of "bar" under the :bar keyword in the context is repetitive. I tried to see if I could do something similar to the expects macro and use it to set value in the context hash besides verifying the key is there. Since blocks in Ruby have well defined closures, peeping in and setting values are not feasible. I chose Context accessors with the promised keys, this way when a value is being set through these, LightService will put it in the context for you.
The above example can be further simplified:

class FooAction
  include LightService::Action
  expects :baz
  promises :bar

  executed do |context|
    context.bar = context.baz + 2
  end
end

Now look how we went from dealing with items in the hash explicitly to focusing on the logic itself:

class FooAction
  include LightService::Action
  expects :baz
  promises :bar

  executed do |context|
    # No need to fetch item from the context
    # baz = context.fetch(:baz)

    context.bar = context.baz + 2

    # No need to add the item to the context
    # context[:bar] = bar
  end
end

Feel free to follow the same refactoring in this spec.

You could argue that this forces you to use a DSL and it's not saving a line of code for you. I hear you, but keep in mind, the expects and promises macro does a whole lot more work than just pulling and putting items in and out of the context: it provides an input/output contract for the action.

With the knowledge of what the inputs and outputs of actions are, the time when I can verify the keys in the Organizer pipeline is not far. I should be able to ask the Organizer to verify the order of actions, as actions might need a product from an action that was executed earlier in the Organizer dictated pipeline. Dependency check FTW!

Sunday, April 27, 2014

Tracking Progress of a Rails Rewrite

I inherited a challenging codebase about 14 months ago. The code did not have tests, there were methods with 100-200 lines of code in them filled with conditionals and iterators. It was obvious: we needed a rewrite. Ok, we were not thinking about The Big Rewrite, but we knew the code had to be cleaned up. I had all the support from the leadership team, but I was asked for one thing: provide a metric to track progress.

A few months went by and I did not have an answer. I couldn’t tell how fast or slow we can get done with the cleanup. Is it going to be six months, one year, maybe two? I did not know what to say.

My goal was extracting business logic from Rails controllers and models and putting them into lib/services. I wanted to structure the code into stateless, reusable actions with LightService, decoupling it from Rails as much as possible. I trusted these services as test coverage for them was fairly high. I knew no matter what business logic I had to implement, the small service classes were able to take anything I would throw at them.

The app used - the now unsupported - Data Mapper library that we wanted to get out of and transition over to Active Record. We put all our AR classes in the app/models/ar directory under the "AR" namespace. We kept these models clean, well tested. Now we trusted everything under lib/services and app/models/ar.

We also started to extract logic into RESTful controllers that had very little logic in them. These controllers were only a handful, maybe half a dozen. I realized we did not do much action clean up in the existing controllers. In fact, we shifted the responsibility to new controllers and services that we trusted.

One of my favorite Ruby code analysis tool is flog. Flog gives you complexity points based on "ABC" metrics: assignments, branches and conditionals. You can run flog against your entire controller and model code and you get a complexity point. If you don't have much logic in the views or JavaScript, that number is your application's complexity.

Comparing trusted and untrusted total lines of code can provide a number, but I am not sure how much I could trust that. 10 lines of really crappy code loaded with iterators and conditionals compared to 10 lines of clean, readable and tested code just does not provide a one-to-one ratio. Why not looking at this problem from the complexity side? 5 point flog complexity can be on 1 single line in a crappy code, but it can be on 4 different lines in a method in the cleaned up code. Amount of coded logic should be expressed in complexity points and not in the number of lines of code.

I realized I could actually trust the flog complexity points to compare the trusted and untrusted code ratio. I easily calculated the total controller complexity. By subtracting the trusted controller complexity from the total complexity I had the untrusted complexity for controllers. I did the same for models. I put all the complexity from lib/services under the trusted bucket. Deviding the total trusted complexity by the untrusted code complexity provided the trusted/untrusted code ratio.

Here is an example of how the calculation worked:

Total controller complexity:8945
Trusted controller complexity:489
Untrusted controller complexity (8945 - 489):8456
 
Total model complexity:1498
Trusted model complexity:249
Untrusted model complexity (1498 - 249):1249
 
Trusted services complexity:845
 
Untrusted total complexity:9705
Trusted total complexity:1583
 
Trusted/Untrusted code ratio:1583/9705 * 100 = 16.3%

The numbers in the example above are made up, they don't reflect the code of my current employer.

A month later you can do the same calculation and you’ll see that the Trusted/Untrusted code ratio is 19.5%. Well, look at that, 3% of your code just gained trust! That new 3% of the code is easy to change as it's small, passes all the tests, communicates intent and has no duplication.

By yielding 3% more trusted code in a month, you will need more than 2 years to clean up the existing code base unless you can accelerate the code clean up somehow.

Tuesday, March 4, 2014

Group By In Plain Ruby

I had to work with this code recently, and it just did not feel right:

class FindsEmployeesByLocations
  def self.from(employee_locations=[])
    locations = Hash.new
    employee_locations.each do |location|

      if !locations.key?(location.city)
        locations[location.city] = Array.new;
      end

      locations[location.city].push(location);
    end

    return locations
  end
end
A few things stood out:
  1. There is a locations hash
  2. The each iterator adds items to the hash based on a condition
  3. Returns the locations hash

Declaring a collection and adding items to it by iterating over the source collection is an infection that people with imperative languages have. With a little bit of functional thinking I was certain this code can be simplified.

Just to be on the safe side I added specs around this before I refactored it:

describe User do
  ...

  context "when the employee locations collection is empty" do
    specify "employees by locations is empty" do
      expect(FindsEmployeesByLocations.from([])).to be_empty
    end
  end

  context "when there are 3 employees with 2 locations" do
    subject { FindsEmployeesByLocations.from(employee_locations) }

    it "has only 2 locations" do
      expect(subject.keys.count).to eq(2)
    end

    specify "first locations has 2 users" do
      expect(subject.keys.first).to eq("Chicago")
      chicago_location = subject["Chicago"]

      expect(chicago_location.count).to eq(2)
      expect(chicago_location.map(&:user).map(&:name)).to eq(%w(John Kate))
    end

    specify "last locations has 1 user" do
      expect(subject.keys.last).to eq("New York")
      new_york_location = subject["New York"]

      expect(new_york_location.count).to eq(1)
      expect(new_york_location.first.user.name).to eq("James")
    end

  end
end
Everything passed, I was ready to play with the code.

First I thought I need to use the reduce method. I tried that, but it did not work. Then I started to think about what this piece of code is doing. I realized it's grouping entities based on keys. I was certain Ruby has a group_by method and I was right: there it was.

All that code can be replaced with one beautiful line:

class FindsEmployeesByLocations
  def self.from(employee_locations=[])
    employee_locations.group_by(&:city)
  end
end
The method, or even this class is unneeded for calling something as simple and elegant as Ruby's group_by method.

Be skeptical when you see an empty collection followed by an iterator. If you look closely, you will see that the code can be simpler by using one of Ruby's enumerable functions.

You can find the entire example in this gist.

Saturday, February 22, 2014

Learning Clojure One Failing Test at a Time

I learn a new language just like I discover a new algorithm in a language I already know: one failing test at a time. The advantage of discovering a language this way is deeper learning. If I read something in a book, try it in the REPL, I forget it by next week. However, writing a failing test first, describing what a function should do, I realized my learning is deeper.

I also like to keep around things I try as a reference. Once I type it in the REPL, unless I save my session somehow, the information goes away. I am unhappy when I make a mistake on the third line in the REPL, and I have to start the whole thing over. I also caught myself looking up things in tests I tried a few weeks ago.

I can try this in the REPL:

user => (conj [1 2 3] 4 5)
  [1 2 3 4 5]

Or I could fire up a new project using Leiningen with lein new learning, add a new test touch test/learning/vector_tests.clj and do something similar in a test:
(ns learning.vector-test
  (:require [clojure.test :refer :all]))

(deftest a-vector-test
  (testing "conjoining elements to a vector"
    (is (= [1 2 3 4 5] (conj [1 2 3] 4 5)))))
I run the test and everything works:
lein test learning.vector-test
Ran 1 tests containing 1 assertions.
0 failures, 0 errors.

The next thing I try is removing the last element from a vector. The Clojure pop function does just that. Here is what I add to my test:

 ..
  (testing "removing the last element from a vector"
    (is (= [1 2 3] (pop [1 2 3 4])))))

You see where this is going. It's a bit more typing, but I'm building up my own reference guide as I learn new things. I also get a deeper knowledge faster by practicing this way.

Why Clojure’s own test framework does not have a colored output is beyond me. I am not ready to send a pull request for it just yet. But if you are as bothered as I am to look at a non-colored test reporter, you need to install difftest as a Leiningen plugin. You need to create or edit your ~/.lein/profiles.clj file as it's described here.

Once you successfully installed the plugin, you go from this:

To that:

The REPL is great for trying short things quickly. As soon as my example reaches the second line I question myself if I really should continue it here or just put the code in a test. I don't enjoy using the REPL as an editor, but as a tool where I can try things, it works!

Thursday, December 26, 2013

Test Driving the FizzBuzz Kata In Clojure

I've been enjoying my journey down the path of functional languages. I started with Clojure, than looked at Erlang, and now I am back at Clojure again. This post does not try to explain why you should look at functional languages, I assume you passed that since you're reading this blog post.

The books will teach you the basic concepts. Those ideas vanish fast unless I practice them with a project or some kind of challenge. Programming quizzes or coding puzzles are a good way to exercise a new language. I usually start with the simple ones, and I work my way towards the more complex projects. The FizzBuzz kata is on the easier side, I was even asked to code it on a white board not too long ago.

 

Here is how I solved the FizzBuzz kata in Clojure test driving it with its own test-is tool. I describe every changes I made, feel free to follow along by typing in the way I did it.

I'll assume you have Clojure and Leiningen installed on your computer. Getting these tools is simple thanks to Homebrew on OSX. Please do a Google search if you don't have them already installed and you're using an OS other than OSX. I am using Clojure 1.5.1 version at the time of this writing.

I generated a skeleton project with Leiningen:lein new app fizzbuzz. The directory structure had a src and a test directory. lein test runs the tests and lein run executes the program.

I put all my code in the src/fizzbuzz/core.clj and in the test/fizzbuzz/core_test.clj files. I write code in Vim, and I use a vertical split to look at the test and program files in the same window. I usually have the test on the left, and the code under test on the right hand side.

Here is the first failing test I wrote:

(ns fizzbuzz.core-test
  (:require [clojure.test :refer :all]
            [fizzbuzz.core :refer :all]))

(deftest fizz-buzz-printer-test
  (testing "with 1"
    (is (= "1\n" (fizz-buzz-printer 1)))))
I provided the skeleton for the fizz-buzz-printer function this way:
(ns fizzbuzz.core
  (:gen-class))

(defn fizz-buzz-printer [limit])

(defn -main
  "I don't do a whole lot ... yet."
  [& args]
  ;; work around dangerous default behaviour in Clojure
  (alter-var-root #'*read-eval* (constantly false))
  (println "Hello, World!"))
When I ran the test with lein test, this is the error I had:

FAIL in (fizz-buzz-printer-test) (core_test.clj:7)
with 1
expected: (= "1\n" (fizz-buzz-printer 1))
  actual:
 (not (= 1
 nil))

Ran 1 tests containing 1 assertions.
1 failures, 0 errors.
Tests failed.

The simplest thing that could possibly work is this:

(ns fizzbuzz.core
  (:gen-class))

(defn fizz-buzz-printer [limit]
  "1\n")

...
Please note that I omitted the -main function as it's not changed yet. I ran the tests, and it all passed:

Ran 1 tests containing 1 assertions.
0 failures, 0 errors.

Great! Now I am on to the next test:

...

(deftest fizz-buzz-printer-test
  (testing "with 1"
    (is (= "1\n" (fizz-buzz-printer 1))))
  (testing "with 2"
    (is (= "1\n2\n" (fizz-buzz-printer 2)))))
The following code change made the test pass:
...

(defn fizz-buzz-printer [limit]
  (if (= 2 limit)
    "1\n2\n"
    "1\n"))

...
A conditional won't serve me long to print out numbers. I refactored the function this way:
...

(defn fizz-buzz-printer
  ([output current limit]
    (let [product (str output current "\n")]
      (if (< current limit)
        (fizz-buzz-printer product (+ 1 current) limit)
        product)))
  ([limit]
    (fizz-buzz-printer "" 1 limit)))

...
This might need a little explanation. I chose recursion instead of using a loop. The fizz-buzz-printer function is overloaded: it accepts 1 (the limit) or 3 arguments (the output, current value and limit). The formatted string is captured in the product value. If the current value in the cycle is less than the limit I call the same function but the current value is incremented by one, and if not, I know I reached the limit and just return the formatted string - the product.

With this code I should be able to print the numbers on the screen followed by a line break. I wrote a quick - temporary - test to verify that (see the last assert):

...

(deftest fizz-buzz-printer-test
  (testing "with 1"
    (is (= "1\n" (fizz-buzz-printer 1))))
  (testing "with 2"
    (is (= "1\n2\n" (fizz-buzz-printer 2))))
  (testing "with 4"
    (is (= "1\n2\n3\n4\n" (fizz-buzz-printer 4)))))

I was ready for the fun part of this kata! For every number divisible by 3 I had to print out the word: "Fizz".
First I wrote the failing test:

...

(deftest fizz-buzz-printer-test
  (testing "with 1"
    (is (= "1\n" (fizz-buzz-printer 1))))
  (testing "with 2"
    (is (= "1\n2\n" (fizz-buzz-printer 2))))
  (testing "from 1-3"
    (is (= "1\n2\nFizz\n" (fizz-buzz-printer 3)))))
The error was obvious:

FAIL in (fizz-buzz-printer-test) (core_test.clj:11)
from 1-3
expected: (= "1\n2\nFizz\n" (fizz-buzz-printer 3))
actual: (not (= "1\n2\nFizz\n" "1\n2\n3\n"))

Ran 1 tests containing 3 assertions.
1 failures, 0 errors.
Tests failed.

I was expecting the word Fizz, but I was getting the number 3. That logic was missing. Here is how I added that:

...

(defn fizz-buzz-printer
  ([output current limit]
    (let [product (if (= 3 current)
                    (str output "Fizz\n")
                    (str output current "\n"))]
      (if (< current limit)
        (fizz-buzz-printer product (+ 1 current) limit)
        product)))
  ([limit]
    (fizz-buzz-printer "" 1 limit)))

...
I felt generating the formatted string - the product value - put way too much logic in the let function. I extracted out that logic into its own function called format-output:
...

(defn- format-output [output current]
  (if (= 3 current)
    (str output "Fizz\n")
    (str output current "\n")))

(defn fizz-buzz-printer
  ([output current limit]
    (let [product (format-output output current)]
      (if (< current limit)
        (fizz-buzz-printer product (+ 1 current) limit)
        product)))
  ([limit]
    (fizz-buzz-printer "" 1 limit)))

...
The function format-output is private, it's only visible within its own namespace thanks to declaring it with defn-.
The increased complexity in the let function triggered the "extract function" refactoring. I felt the format-output function should be responsible for deciding if it has to print the number or the words "Fizz", "Buzz" or "FizzBuzz".

The next test was simple, I wanted to make sure the logic worked from zero to four. I did not have to modify the code for it:

...

(deftest fizz-buzz-printer-test
  (testing "with 1"
    (is (= "1\n" (fizz-buzz-printer 1))))
  (testing "with 2"
    (is (= "1\n2\n" (fizz-buzz-printer 2))))
  (testing "from 1-3"
    (is (= "1\n2\nFizz\n" (fizz-buzz-printer 3))))
  (testing "from 1-4"
    (is (= "1\n2\nFizz\n4\n" (fizz-buzz-printer 4)))))
I reached a point with my tests where I had to make my code a bit easier to test. I did not want to write tests that compares more than 3 numbers from the fizz-buzz-printer. I felt 3 is a large enough set to verify the boundaries. I added a new test for this:
...

(deftest fizz-buzz-printer-test
  (testing "with 1"
    (is (= "1\n" (fizz-buzz-printer 1))))
  (testing "with 2"
    (is (= "1\n2\n" (fizz-buzz-printer 2))))
  (testing "from 1-3"
    (is (= "1\n2\nFizz\n" (fizz-buzz-printer 3))))
  (testing "from 1-4"
    (is (= "1\n2\nFizz\n4\n" (fizz-buzz-printer 4))))
  (testing "from 3-4"
    (is (= "Fizz\n4\n" (fizz-buzz-printer 3 4)))))
Since I did not have the function override for 2 arguments, the test failed:

ERROR in (fizz-buzz-printer-test) (AFn.java:437)
from 3-4
expected: (= "Fizz\n4\n" (fizz-buzz-printer 3 4))
  actual: clojure.lang.ArityException: Wrong number of args (2) passed to: core$fizz-buzz-printer

I added the function override which looked almost identical to the function with one argument:

...

(defn fizz-buzz-printer
  ([output current limit]
    (let [product (format-output output current)]
      (if (< current limit)
        (fizz-buzz-printer product (+ 1 current) limit)
        product)))
  ([start limit]
   (fizz-buzz-printer "" start limit)) ; added function with 2 arguments
  ([limit]
    (fizz-buzz-printer "" 1 limit)))

...
All the tests passed. However, this code had duplication: the unary function (method with one argument) initialized the output just like the binary function. I decided to remove this duplication by changing the unary function to call the binary function that calls the ternary one.
...

(defn fizz-buzz-printer
  ([output current limit]
    (let [product (format-output output current)]
      (if (< current limit)
        (fizz-buzz-printer product (+ 1 current) limit)
        product)))
  ([start limit]
   (fizz-buzz-printer "" start limit))
  ([limit]
    (fizz-buzz-printer 1 limit))) ; does not initializes the output

...
I was now ready to zoom into the ranges where the program had to produce the different words instead of numbers. The next test did just that:
...

(deftest fizz-buzz-printer-test
  (testing "with 1"
    (is (= "1\n" (fizz-buzz-printer 1))))
  (testing "with 2"
    (is (= "1\n2\n" (fizz-buzz-printer 2))))
  (testing "from 1-3"
    (is (= "1\n2\nFizz\n" (fizz-buzz-printer 3))))
  (testing "from 1-4"
    (is (= "1\n2\nFizz\n4\n" (fizz-buzz-printer 4))))
  (testing "from 3-4"
    (is (= "Fizz\n4\n" (fizz-buzz-printer 3 4))))
  (testing "from 4-5"
    (is (= "4\nBuzz\n" (fizz-buzz-printer 4 5)))))
I did the simplest thing that could possibly work: I used a nested conditional:
...

(defn- format-output [output current]
  (if (= 3 current)
    (str output "Fizz\n")
    (if (= 5 current) ; introduced this nested conditional
      (str output "Buzz\n")
      (str output current "\n"))))

...
Everything passed again, but this code was ugly. Here is how I used cond to refactor it:
...

(defn- format-output [output current]
  (cond
    (= 3 current) (str output "Fizz\n")
    (= 5 current) (str output "Buzz\n")
    :else (str output current "\n")))

...
My next test covered the range from 4-6, where the word "Fizz" should be printed out for the number 6.
...

(deftest fizz-buzz-printer-test
  (testing "with 1"
    (is (= "1\n" (fizz-buzz-printer 1))))
  (testing "with 2"
    (is (= "1\n2\n" (fizz-buzz-printer 2))))
  (testing "from 1-3"
    (is (= "1\n2\nFizz\n" (fizz-buzz-printer 3))))
  (testing "from 1-4"
    (is (= "1\n2\nFizz\n4\n" (fizz-buzz-printer 4))))
  (testing "from 3-4"
    (is (= "Fizz\n4\n" (fizz-buzz-printer 3 4))))
  (testing "from 4-5"
    (is (= "4\nBuzz\n" (fizz-buzz-printer 4 5))))
  (testing "from 4-6"
    (is (= "4\nBuzz\nFizz\n" (fizz-buzz-printer 4 6)))))
This test failed again as I was only checking for the number three and not for numbers divisible by three without a remainder. I changed the format-output function to use the modulus operator:
...

(defn- format-output [output current]
  (cond
    (= 0 (mod current 3)) (str output "Fizz\n")
    (= 5 current) (str output "Buzz\n")
    :else (str output current "\n")))

...
All the tests now passed again.

I suspected the same error at number 10, therefore my next test was around it (between 9 and 11):

...

(deftest fizz-buzz-printer-test
  (testing "with 1"
    (is (= "1\n" (fizz-buzz-printer 1))))
  (testing "with 2"
    (is (= "1\n2\n" (fizz-buzz-printer 2))))
  (testing "from 1-3"
    (is (= "1\n2\nFizz\n" (fizz-buzz-printer 3))))
  (testing "from 1-4"
    (is (= "1\n2\nFizz\n4\n" (fizz-buzz-printer 4))))
  (testing "from 3-4"
    (is (= "Fizz\n4\n" (fizz-buzz-printer 3 4))))
  (testing "from 4-5"
    (is (= "4\nBuzz\n" (fizz-buzz-printer 4 5))))
  (testing "from 4-6"
    (is (= "4\nBuzz\nFizz\n" (fizz-buzz-printer 4 6))))
  (testing "from 9-11"
    (is (= "Fizz\nBuzz\n11\n" (fizz-buzz-printer 9 11)))))
The test failed, I received 10 instead of "Buzz", I adjusted the second conditional to use the modulus function as well:
...

(defn- format-output [output current]
  (cond
    (= 0 (mod current 3)) (str output "Fizz\n")
    (= 0 (mod current 5)) (str output "Buzz\n")
    :else (str output current "\n")))

...
This was great! Now I had to write code for one more scenario: for the numbers divisible by 5 and 3 I had to print the word "FizzBuzz" instead of "Fizz" or "Buzz". My last test did just that:
...

(deftest fizz-buzz-printer-test
  (testing "with 1"
    (is (= "1\n" (fizz-buzz-printer 1))))
  (testing "with 2"
    (is (= "1\n2\n" (fizz-buzz-printer 2))))
  (testing "from 1-3"
    (is (= "1\n2\nFizz\n" (fizz-buzz-printer 3))))
  (testing "from 1-4"
    (is (= "1\n2\nFizz\n4\n" (fizz-buzz-printer 4))))
  (testing "from 3-4"
    (is (= "Fizz\n4\n" (fizz-buzz-printer 3 4))))
  (testing "from 4-5"
    (is (= "4\nBuzz\n" (fizz-buzz-printer 4 5))))
  (testing "from 4-6"
    (is (= "4\nBuzz\nFizz\n" (fizz-buzz-printer 4 6))))
  (testing "from 9-11"
    (is (= "Fizz\nBuzz\n11\n" (fizz-buzz-printer 9 11))))
  (testing "from 14-16"
    (is (= "14\nFizzBuzz\n16\n" (fizz-buzz-printer 14 16)))))
The error was what I expected: the program only printed out the word "Fizz" instead of "FizzBuzz". Adding the modulus check for 15 made this last test to pass:
...

(defn- format-output [output current]
  (cond
    (= 0 (mod current 15)) (str output "FizzBuzz\n")
    (= 0 (mod current 3)) (str output "Fizz\n")
    (= 0 (mod current 5)) (str output "Buzz\n")
    :else (str output current "\n")))

...
All my tests passed!

Ran 1 tests containing 9 assertions.
0 failures, 0 errors.

I also wanted to see the program in action by running it with leain run. Here is how I changed the main function:

...

(defn -main
  [& args]
  ;; work around dangerous default behaviour in Clojure
  (alter-var-root #'*read-eval* (constantly false))
  (print (fizz-buzz-printer 100)))

And that's it! Please take a look at the final solution in this Gist.
Hope you had as much fun reading this as I had preparing it.

Happy New Year everyone!