Refactor by introducing a formatter that sends logging events to multiple formatters

[mattbrictson]

Here's an idea suggested by @robd:

One thing I have considered is adding support to SSHKit for multiple formatters. I was thinking this might allow us to remove all the SSHKit Pretty formatting related tests from Airbrussh, and remove the management of the Pretty formatted file Logger. One gotcha is the 'last 20 lines of output' currently relies on Airbrussh having access to the pretty formatter.

Perhaps how this could work is that we introduce a new formatter to handle the logging duplication. In other words, logging events come into this formatter and are duplicated and emitted to multiple destination formatters.

This "dispatcher" would eliminate the need for dealing with the Pretty logger inside Airbrussh::Formatter itself, which would simplify the code and tests quite a bit.

As @robd mentions, the one coupling that still remains is the "last 20 lines of output" problem. Perhaps a separate decorator could handle the responsibility of buffering Pretty's IO? Sounds like some more discussion needed on this point.

Related:

Another thing which I don't like is when I removed color codes from the log file it unfortunately made the 'last 20 lines of output' message uncolored. Ideally we would show last 20 lines of output with colors on the terminal, but not write character codes to the log file.

In any case, I think it makes sense to introduce the multi-formatter handling in airbrussh first, and then we can contribute it to SSHKit if it proves to be flexible and useful.

[mattbrictson]

@robd What do you think of this proposal?

Step 1: Introduce DelegatingFormatter

DelegatingFormatter would conform to the SSHKit::Formatter API but simply delegate all the API calls to one or more other formatters. This would allow a single formatter to be registered from SSHKit's perspective, but the logging events could be processed by multiple formatters.

DelegatingFormatter would also respond to on_deploy_failure and forward it to formatters that support it.

Step 2: Change SSHKit::Formatter::Airbrussh to inherit from DelegatingFormatter

This would be a simple refactor to allow for step 3.

module SSHKit
  module Formatter
    class Airbrussh < Airbrussh::DelegatingFormatter
      def initialize(io, config=Airbrussh.configuration)
        super
        formatters << Airbrussh::Formatter.new(io, config)
      end
    end
  end
end

Step 3: Move log file code out of Airbrussh::Formatter and into Airbrussh::PrettyLogFileFormatter

PrettyLogFileFormatter would take over this functionality from Airbrussh::Formatter:

• create_log_file_formatter
• write_banner
• on_deploy_failure (since it knows about @log_file)
• Delegating all logging calls to SSHKit::Formatter::Pretty (it could subclass Pretty)

Step 4: Wire it all up

Now we have two formatters that are cleanly separated, and the top level SSHKit::Formatter::Airbrussh ties them together:

module SSHKit
  module Formatter
    class Airbrussh < Airbrussh::DelegatingFormatter
      def initialize(io, config=Airbrussh.configuration)
        super
        file = config.log_file
        formatters << Airbrussh::Formatter.new(io, config)
        formatters << Airbrussh::PrettyLogFileFormatter.new(file) unless file.nil?
      end
    end
  end
end

How does that look?

[robd]

I think that looks great. Here are a couple of thoughts:

• Should the on_deploy_failure method actually be on the formatters at all? Since the method only depends on the log file for reading, I feel that perhaps this is a different concern to formatting. We could simply inline this into the capistrano failure hook:

namespace :deploy do
  task :failed do
    if (log_file = Airbrussh.configuration.log_file)
      err = Airbrussh::Console.new($stderr)
      err.print_line
      err.print_line(red("** DEPLOY FAILED"))
      err.print_line(yellow("** Refer to #{log_file} for details. "\
                            "Here are the last 20 lines:"))
      err.print_line
      system("tail -n 20 #{log_file.shellescape} 1>&2")
    end
  end
end

• Ideally, we should replace the use of tail -n 20 with pure ruby, but would need to do something efficient to handle large files. I'm surprised we haven't seen error reports for this for people using windows. This is should probably be a separate PR.

• Delegating all logging calls to SSHKit::Formatter::Pretty (it could subclass Pretty)

  I think, if possible, we should delegate to Pretty rather than subclass.

• Perhaps DelegatingFormatter could have a non mutable list of formatters and we could use configuration as a factory for the required formatters:

module SSHKit
  module Formatter
    class Airbrussh < Airbrussh::DelegatingFormatter
      def initialize(io, config=Airbrussh.configuration)
        super(config.formatters(io))
      end
    end
  end
end

• I'm not sure about the write_banner method. It's kind of complicated, because, whilst it is concerned with whether the log_file is configured, it uses the print_line and blue formatter methods. One option would be to pass the normal formatter to the pretty one as constructor parameter, and then call the info method on the formatter public API to output the lines:

# Configuration
def formatters(io)
  formatters = [Airbrussh::Formatter.new(io, self)]
  formatters << Airbrussh::PrettyLogFileFormatter.new(@log_file, formatters.first) unless @log_file.nil?
  formatters
end

#  PrettyLogFileFormatter
def write_banner
  return unless config.banner
  if config.banner == :auto
    return if @log_file.nil?
    normal_formatter.info("Using airbrussh format.")
    #NB Not sure if blue would work here because `info` already makes the output gray
    normal_formatter.info("Verbose output is being written to #{blue(@log_file)}.")
  else
    print_line config.banner
  end
end

Anyway, hope this is of some help, happy to look at a PR if you have time to work on it.

[mattbrictson]

@robd Thanks for the feedback. Agreed on all points. My only concern is that I'm not sure the write_banner change you suggested is any cleaner. I'll put together a PR early next week and we can take it from there.

[mattbrictson]

We could simply inline [on_deploy_failure] into the capistrano failure hook

Done in 008fb47.

[mattbrictson]

Closed via #38