Mike Slinn
Mike Slinn

Custom Logging in Jekyll Plugins

Published 2020-12-28. Last modified 2022-04-05.
Time to read: 4 minutes.

This page is part of the jekyll collection, categorized under Jekyll, Ruby.

Debugging Jekyll plugins can be a challenge, but a configurable logging facility can be a big help. Writing puts statements to generate output works, but puts statements are tedious to control because you must comment and uncomment lines that generate output as you work through issues. It is better to set up another standard Ruby logger, perhaps outputting to STDOUT, STDERR, or a file, and control the output by setting the log level for the plugin’s logger.

Loggers are cheap,
when used correctly

Loggers are cheap – and easy to set up. Be sure to set the log level to warn or error when you are not debugging, and place the expression to be evaluated within a block (more on this later), so site generation goes full speed.

Use a new logger for each plugin that you write. This article describes jekyll_plugin_logger, a Ruby gem that I created that allows you to quickly make custom loggers for your plugins. This plugin was originally called logger_factory, but it was renamed for version 2 because it was completely rewritten and became incompatible with previous versions.

Colored Log Output

It can be difficult to find what you are looking for as you watch miles and miles of log output spew onto your console, hour after hour, while you work on a problem. Colored output can be a big help. Jekyll relies on the colorizer gem, so you can use colors on any terminal output written by puts, or sent to a log that writes to STDERR or STDOUT. It is easy to do this, just append a suffix to a string that indicates the color you want that string to be displayed with. For example: 

puts "Green text and ham!".green
log.warn "Red text at night, sailor's delight".red

Green text and ham!
Red text at night, sailor's delight.

Supported colors are:

  • red
  • black
  • green
  • yellow
  • magenta
  • white
  • blue
  • cyan
  • bold

First, the Obvious But Wrong Way

You can send a message to Jekyll.logger from a plugin like this: 

Jekyll.logger.debug "Hello, world"
Jekyll.logger.info  "Hello, world"
Jekyll.logger.warn  "Hello, world"
Jekyll.logger.error "Hello, world"

However, the default Jekyll.logger.log_level is :info. This is a global setting that affects all of Jekyll because only one Logger is used throughout Jekyll. It outputs to STDERR.

If you want to control the output by adjusting log levels, you will quickly realize that attempting to adjust the log_level for Jekyll’s logger singleton is problematic. This is because when you need to see verbose output from your plugin, verbose output from the rest of Jekyll will spew all over your terminal.

Adjusting Jekyll.logger.log_level

Jekyll.logger is under-documented. This section is just provided to round out your understanding of how logging works in Jekyll. Please do not attempt to use Jekyll’s logger in your plugins – instead, use the jekyll_plugin_logger, described below, which is packaged as a Ruby gem for convenience.

To set Jekyll.logger.log_level (globally), specify the --verbose / -V or --quiet / -q options when starting Jekyll: 

$ bundle exec jekyll build --verbose  # Sets log_level to :debug

$ bundle exec jekyll build --quiet  # Sets log_level to :error

$ JEKYLL_ENV=development bundle exec jekyll serve --verbose

$ JEKYLL_ENV=development bundle exec jekyll serve --quiet

You can also reset the Jekyll log level from within a Jekyll plugin like this: 

Jekyll.logger.adjust_verbosity(:verbose => true)

I found that _config.yml has no effect on Jekyll.logger.log_level; the following entry does nothing: 

quiet: true

Jekyll_plugin_logger To the Rescue!

Jekyll_plugin_logger provides 2 classes:

  1. PluginMetaLogger – PluginLogger factory and top-level logger.
  2. PluginLogger – Logger dedicated to a specific Jekyll plugin.

PluginMetaLogger provides each Jekyll plugin its own PluginLogger instance. This allows each plugin's log level to be individually controlled.

  1. debug level output is colored magenta.
  2. info level output is colored cyan.
  3. warn level output is colored yellow.
  4. error level output is colored red.

The current version does not allow the colors for each log level to be customized. Please create an issue if that feature would be useful to you.

Background

As you may know, Jekyll sets site.config by parsing _config.yml as YAML. When Jekyll_plugin_logger is asked to create a logger, it looks within site.config for a key corresponding to the plugin progname, which is by default the name of the enclosing scope (a module or class) that the plugin is created for.

For example, if the plugin's class is called MyPlugin1, then an entry called plugin_loggers.MyPlugin1 would be read from the site configuration, if present. If no such entry is found, then the log_level for that logger is set to info.

_config.yml
plugin_loggers:
  PluginMetaLogger: info
  MyPlugin1: warn
  MyPlugin2: error
  MyPlugin3: debug

When the plugin is loaded, a Jekyll site hook is invoked that instantiates the PluginMetaLogger singleton. At this time, the plugin_loggers key values are retrieved from the Jekyll site configuration. PluginMetaLogger will construct a PluginLogger instance for each value found, with the log level specified in _config.yml. PluginMetaLogger.instance.config holds the site.config read from _config.yml. In the above _config.yml the PluginMetaLogger is constructed with log level info.

Example Usage

Below is a high-level example of how to create and use this plugin. The site.config is retrieved from PluginMetaLogger.instance.config; for some plugins, that information is provided as a site parameter. In that circumstance, site.config is a less verbose method of obtaining the same information.

MyPlugin.rb
module MyPlugin1
  @logger = PluginMetaLogger.instance.new_logger(self, PluginMetaLogger.instance.config)

  def my_plugin_method(text, query)
    @logger.debug { "text='#{text}' query='#{query}'" }
    # TODO write the rest of the method
  end

  # TODO write the rest of the plugin
end

PluginMetaLogger.instance.info { "Loaded my_plugin_1 v0.1.0 plugin." }
# Register MyPlugin1 here

By default, the above causes output to appear on the console like this: 

INFO PluginMetaLogger: Loaded my_plugin_1 v0.1.0 plugin.
DEBUG MyPlugin1:  text='Hello world' query='Bogus query'

Take a look at my begin_end plugin for a complete example.

Do Not Use Simple Strings

These log messages are always computed, needed or not:

MyPlugin.rb
@logger.info "Information message"
@logger.warn("Warning message")
@logger.error "Error message"

Use Blocks Instead

The following blocks are not evaluated unless log_level for that requires them to be. This means your Jekyll site will regenerate quickly when log_level is set high enough to suppress most output.

MyPlugin.rb
@logger.info { "Information message" }
@logger.warn { "Warning message" }
@logger.error { "Error message" }

Proof That Blocks Are Lazily Evaluated

Below is a simple example that demonstrates Ruby blocks are lazily evaluated. Output from the block passed to the test method results each time the block is evaluated. As you can see, it is never evaluated. This is because blocks in Ruby are only evaluated when invoked, they are somewhat similar to call by reference, and are definitely not call by value.

Shell
$ irb
irb(main):001:0> def test; yield if false; end
=> :test 

irb(main):002:0> test { puts "hi" }
=> nil

For More Information

More information is available about this plugin from its GitHub project at github.com/mslinn/jekyll_plugin_logger. This plugin is provided as a Ruby gem at rubygems.org/gems/jekyll_plugin_logger.

Acknowledgements

Thanks to Ashwin Maroli (@ashmaroli) for his kind assistance.