Productive logging with Athena & Crylog

This article was written for an older version of Athena and is no longer valid. Its content has been integrated into Creating a JSON API with Athena & Granite and Dependency Injection in Crystal.

Also, Crylog has been deprecated in favor of the standard libraries' Log module.

Logging

Logging is an important tool when creating any application. Logging adds information that could be useful for debugging issues, doing analytics, or just gathering user behavior data; all of which can be used to inform future decisions.

However not all logging is equal. Logging should be setup in such a way so that only useful information is logged, depending on the environment.
For example, a developer working on an application would love to see debug level information so that they have all of the possible information available in order to track down issues and find bottlenecks. The application running in the production environment should NOT see debug level logs so that the log files are not cluttered, which causes actual important issues to be lost in the shuffle.

Crylog

Crylog is a new flexible logging framework for Crystal based on Monolog. It allows applications to have multiple named loggers, each with various handlers, processors, formatters.

A handler would be something that does something with a logged message. For example logging to a file or STDOUT. But it could also be sending the message to Sentry, or a database etc.

A processor adds extra data to each message. A good use case of this would be adding user/customer ids to each logged message that would represent the user which caused that message to be logged.

Lastly, a formatter of course determines how a message gets serialized. Formatters allow different styles to be used depending on the handler, as HTML would be great for email handlers but not so much for log files.

When used together, Crylog allows for various loggers to be customized to handle the various aspects of an application. Such as only logging messages that are warnings or higher in the production environment, but all messages during development.

Athena

Athena is an annotation based web framework which uses Crylog as its logging solution. For this article I'm going to be demonstrating some of the benefits that Crylog enables when combined with some neat Athena features, such as Dependency Injection. This will be a continuation of the Blog Article I wrote a few months ago.

Dependency Injection (DI)

One of the newer features of Athena is a service container layer. This allows a project to share useful objects, aka services, throughout the project. These objects live in a special class called the Service Container (SC). Object instances can be retrieved from the container, or even injected directly into classes as a form of constructor DI. While this article is not focused on DI specifically, it will be using it. For more information related to it, see the Athena Docs.

Agenda

First, lets define some goals we wish to achieve via our logging.

• Log some informational messages when articles are created/deleted, or a user logins, or a new user registers, along with some contextual information.
• Both scenarios should be logged to a file, but the development environment should also log to STDOUT.

By default Athena will log all messages to STDOUT and a development.log file when in the development environment, while the production environment logs to a production.log file, but only for warnings and higher. Also since we want to add some custom logic into our loggers, we'll need to define our own configuration.

Security HTTP Handler

In the last tutorial, we created a HTTP::Handler class to handle authorization around the token used in each request. I do have plans for some security related features that I use in this article to be built into Athena itself, however for now it is up to the user to define.

However there are some problems with this approach. As I left off in the previous tutorial, how would we know what user is logged in within our controller actions? To solve this we can create a UserStorage class that will store the current user, so that other classes would have access to it via DI. Lets create a new directory under src called services that I'll put the UserStorage service. Next create a new file called user_storage.cr with the following code. Be sure to require it in your blog.cr file as well.

module Blog
  @[Athena::DI::Register]
  class UserStorage < Athena::DI::ClassService
    # Use a ! property since they'll always be a user defined in our use case.
    # It also defines a nilable getter method to make sure there is a user
    property! user : Blog::Models::User
  end
end

Notice how we are inheriting from Athena::DI::ClassService, this allows Athena to get a list of all services to register, while the @[Athena::DI::Register] allows some configuration on how the service is registered.

Now we can go back to our security handler, get the user storage service, and set the user.

module Blog
  class SecurityHandler
    include HTTP::Handler

    def call(ctx : HTTP::Server::Context) : Nil
      ...
      # Get the user storage service from the container
      user_storage = Athena::DI.get_container.get("user_storage").as(UserStorage)

      # Set the user in user storage
      user_storage.user = Blog::Models::User.find! body[0]["user_id"]

      # Call the next handler
      call_next ctx
    end
  end
end

Then we can go do a similar thing and update the references in the ArticleController.

module Blog::Controllers
  @[Athena::Routing::ControllerOptions(prefix: "article")]
  class ArticleController < Athena::Routing::Controller
    include Athena::DI::Injectable

    def initialize(@request_stack : Athena::Routing::RequestStack, @user_storage : UserStorage); end

    @[Athena::Routing::Post(path: "")]
    @[Athena::Routing::ParamConverter(param: "body", type: Blog::Models::Article, converter: Athena::Routing::Converters::RequestBody)]
    def new_article(body : Blog::Models::Article) : Blog::Models::Article
      # Sets the owner of the blog post as the current authed user
      body.user = @user_storage.user
      body.save
      body
    end

    @[Athena::Routing::Get(path: "")]
    def get_articles : Array(Blog::Models::Article)
      # We are also using the user in UserStorage as an additional conditional in our query when fetching articles
      # this allows us to only returns articles that belong to the current user.
      Blog::Models::Article.where(:deleted_at, :neq, nil).where(:user_id, :eq, @user_storage.user.id).select
    end

    @[Athena::Routing::Put(path: "")]
    @[Athena::Routing::ParamConverter(param: "body", type: Blog::Models::Article, converter: Athena::Routing::Converters::RequestBody)]
    def update_article(body : Blog::Models::Article) : Blog::Models::Article
      body.user = @user_storage.user
      body.save
      body
    end

    @[Athena::Routing::Get(path: "/:article_id")]
    @[Athena::Routing::ParamConverter(param: "article", pk_type: Int64, type: Blog::Models::Article, converter: Athena::Routing::Converters::Exists)]
    def get_article(article : Blog::Models::Article) : Blog::Models::Article
      article
    end

    @[Athena::Routing::Delete(path: "/:article_id")]
    @[Athena::Routing::ParamConverter(param: "article", pk_type: Int64, type: Blog::Models::Article, converter: Athena::Routing::Converters::Exists)]
    def delete_article(article : Blog::Models::Article) : Nil
      article.deleted_at = Time.utc
      article.save
      @request_stack.response.status = HTTP::Status::ACCEPTED
    end
  end
end

We are also able to inject the RequestStack in order to have access to the request/response.

NOTE: Services can only be auto injected, like the ArticleController if the class gets instantiated within the request/response cycle. Classes instantiated outside of it, like the SecurityHandler, do not have access to the same container and services must be fetched manually.

Now that we have our authentication problem resolved we can move onto adding some logging.

Adding Logs

We'll do the two public routes first. Simply go to your AuthController and add a Athena.logger.info "User logged in", Crylog::LogContext{"user_id" => user.id} before the {token: user.generate_jwt}. This would log

[2019-11-20T01:40:40Z] main.INFO: User logged in {"user_id":1}

our message with the id of the user that logged in. We can do a similar thing in our UserController. Add a Athena.logger.info "New user registered", Crylog::LogContext{"user_id" => body.id, "email" => body.email, "first_name" => body.first_name, "last_name" => body.last_name} after saving the user model. This would log that someone registered with some information about that user.

We could also do the same thing in our ArticleController, adding like Athena.logger.info "Article ##{body.id} was created", Crylog::LogContext{"user_id" => @user_storage.user.id}. However we could keep things more DRY by using a Crylog Processor since the ArticleController are authenticated endpoints, which would have a user in the UserStorage.

Let's create a new directory under src called logger that I'll put the processor. Next create a new file called user_processor.cr with the following code. Be sure to require it in your blog.cr file as well.

module Blog
  struct UserProcessor < Crylog::Processors::LogProcessor
    def call(message : Crylog::Message) : Nil
      user_storage = Athena::DI.get_container.get("user_storage").as(UserStorage)

      # Return early if a message was logged in a public endpoint there won't be a user in storage
      return unless user = user_storage.user?

      # Add the current user's id to all log messages
      message.extra["user_id"] = user.id
    end
  end
end

This would add the current user's id to every logged message as part of the message's extra property. It also handles the case where we were logging users logging in and registering, which would not have a user in storage. Another option would be to define a logger specifically for public stuff, but that is a bit overkill for now.

Next we need to tell Crylog to use our processor. We will also handle the 2nd bullet point in our agenda. Within blog.cr module add the following code:

  def Athena.configure_logger
    # Create the logs dir if it doesn't exist already.
    Dir.mkdir Athena.logs_dir unless Dir.exists? Athena.logs_dir
    Crylog.configure do |registry|
      registry.register "main" do |logger|
        handlers = [] of Crylog::Handlers::LogHandler

        if Athena.environment == "development"
          # Log to STDOUT and development log file if in develop env.
          handlers << Crylog::Handlers::IOHandler.new(STDOUT)
          handlers << Crylog::Handlers::IOHandler.new(File.open("#{Athena.logs_dir}/development.log", "a"))
        elsif Athena.environment == "production"
          # Log only to a file if in production env.
          handlers << Crylog::Handlers::IOHandler.new(File.open("#{Athena.logs_dir}/production.log", "a"))
        end

        # Tell crylog to use our processor on the main logger.
        logger.processors = [Blog::UserProcessor.new] of Crylog::Processors::LogProcessors

        logger.handlers = handlers
      end
    end
  end

This method tells Crylog how to configure the loggers to use. As you can see, we are logging to STDOUT and a development.log file when in the dev environment, but only a production file when in the prod environment. Notice we are opening the log file with the a option; this makes makes it so messages are appended to the log instead of completely overwriting it. We are also telling it to use our UserProcessor. For more information regarding the possible logging configurations, checkout the Crylog documentation.

After that, start the server and start doing things to see messages logged. Messages logged in the ArticleController will have the current user id included in the message; just like when a user logs in, but without having to explicitly specify it.

From here additional handlers/processors etc could be defined to also log these messages to Greylog, Sentry, or even send emails if they are of a high enough severity. Crylog allows for all sorts of flexibility when deciding on how best implement logging for your project.

Update November 19, 2019 for some minor polish & changes based on previous tutorial/new Athena version