ChiliLogger

ChiliLogger is a gem developed by Chiligum Creatives for internal use. It is used to monitor our ruby applications and generate logs with some uniformization.

Table of Contents

READ BEFORE CONTRIBUTING

The main thing you need to know before changing Chililogger's source code is this: we send our logs in JSON format and Logstash parses and converts them to Elasticsearch objects, requiring all fields to have consistent primitive types. So suppose you send these logs: 

// first log
{
  "user": {
    "name": "Joe Doe"
  }
}

// second log
{
  "user": "Mary Jane"
}

// third log
{
  "user": {
    "name": {
      "first": "Francis",
      "last": "Coppola"
    }
  }
}

// fourth log
{
  "client": {
    "name": "Angela"
  }
}

After receiving the first log, Logstash will parse it and define that the user field is always an object and that it may have a field called name, which is a string. Notice that it is not mandatory for logs to have a user and a user.name. But, if a log does have these fields, then they must be an object and a string, respectively.

When Logstash receives the second log, it will see an inconsistency, because this time user is a string, not an object. Because of that, Logstash will ignore this log - in other words, this log will not be saved to Elasticsearch. When the third log arrives, the same will happen. It will see that user is consistent with what it expected, but that the field user.name is now an object, intead of being a string as was expected. This log will also be ignored by Logstash. The fourth log would be accepted though, since client.name hasn't been set yet.

So if you are going to change anything in ChiliLogger, you have to keep this in mind: the primitive types of fields in an Elasticsearch index must always be consistent. If your changes generate logs with fields that already existed in the Elasticsearch index, but now have a different primitive type, Logstash will ignore these logs. This is important because Logstash just ignores incorrect logs without raising errors - so it may take a long time before the problem is noticed. If you need to change the type of a previously set field, you will need to create a new index/Logstash and make sure the logs are sent to this new Logstash.

How it works

Overview

ChiliLogger usual Flow

For the time being, only RabbitMQ is supported as the main message broker. Only AWS SQS is available as a fallback broker.

If both the main message broker and the fallback message broker are down, ChiliLogger wil discard the log to keep the application running without raising any error. That's because raising errors would make the app crash and make it impossible to be used while the brokers are down.

Anatomy of a Chiligum Log

The ChiliLogger gem was created to guarantee some level of uniformization in logs generated by all our ruby applications. So, to better understand its functioning and usage, it is helpful to first understand what kind of logs it is trying to generate. An example log would look like the following:

Example Log

{
  "env": "development",
  "layer": "creatives",
  "type": "transaction",
  "service": "videos",
  "action": "create",
  "desc": "development.creatives.transaction.videos.create",
  "user": { 
    "cognito_id": "88", 
    "email": '[email protected]',
    "company_cognito_id": "75",
    "company_name": "Chiligum Creatives",
    "admin_ghost_user": "not_specified"
  },
  "transaction": {
    "modified_records": { 
      "videos": [{ "id": 42, "title": 'Lateralus' }]
    },
    "errors": [],
    "backtrace": [
      "app/views/dashboard/controllers/videos_controller.rb:17 in block 'create'"
    ],
  },
  "ops_metadata": {
    "server_url": "https://app.chiligumvideos.com"
  },
  "timestamp": "2020-06-30T18:08:59-03:00"
}

Below is a short explanation of each one of the log attributes.

Environment

The env attribute is used for tagging the log and tells in which environment the app was running when the log was created. We are mainly concerned with three possible environments: production, staging, and development. Needless to say, logs from a production environment are the most important to us, but staging and development logs can be useful for debugging/testing.

Layer

The layer attribute is also used for tagging and tells us in which layer of the Chiligum platform the log was created. Usually, the layer will correspond to the name of the application/service where ChiliLogger was installed. For instance, it could be 'creatives', 'api', 'render', etc...

Type

Also a tagging attribute, tells what type of log it is. Chiligum has 3 main types of logs:

  • transaction is used for logging transactions made by users, such as creating a campaign, uploading a file to the gallery, etc...
  • uncaught_error is used for logging internal server errors and to help us find problematic points in our applications;
  • monitoring is used to monitor the health of our servers, providing information such as CPU usage, uptime, etc...

ChiliLogger is concerned only with transaction and uncaught_errors, since they are the only ones that can be generated in the application itself. Monitoring logs are created by other monitoring services, like ElasticSearch Beats or AWS Cloudwatch.

Service

The service tagging attribute is used to tell what group of features the user was trying to interact with. Services can be things like 'videos', 'campaigns', 'banners', 'gallery' and will usually have the similar names to the Controllers in an application.

Action

The action tagging attribute describes what action exactly the user was trying to perform in our platform. Usual values for it are 'create', 'update, and 'delete'. Usually, action tags will have similar names to Controllers' methods.

Description

The desc is the last of the tagging attributes and is used to combine all of the previous attributes in a single tag, allowing any person that is examining a log to quickly identify what the log is about. It is structured in the following manner:

"#{env}.#{layer}.#{type}.#{service}.#{action}"

Notice that the tags are separated by a . period. That's because the desc tag is also used to create the routing_key for topic exchanges when ChiliLogger is using RabbitMQ as its MessageBroker.

User

The user stores the main infos about the user whose request generated the log. The user is an object that accepts five attributes:

  • cognito_id, the user's global ID, the one the identifies it in Cognito's DB;
  • email, so we can easily know who the user is;
  • company_cognito_id, the global ID of the user's company;
  • company_name;
  • ghost_user_cognito_id, for cases when admin users can log as other users. In these cases, the admin's global ID should be stored in the ghost_user_cognito_id;

Main Content

(Transaction | Error)

The main_content will have all other data relevant to the log. The main content of a log will be stored in a key with the same name as the log type. So a transaction log, as in the example above, willhave its main_content stored in the transaction field. In an error log, it would be in an error field. This is a very customizable attribute and its content will be very context relative. But as often as possible, we want it to store errors, backtrace and the records that were modified (modified_records) during the transaction, so we can later audit them, if needed. The modified_records are also used for creating analytics reports.

Ops Metadata

Based on the configuration data(:server_url, :cloud_provider) that is passed to ChiliLogger when it is initialized, the log will also have metadata about the server itself where the application is running.

Timestamp

ChiliLogger automatically adds a timestamp to the log.

A Primer on RabbitMQ and ElasticSearch

Since Chiligum's logging system is entirely based on RabbitMQ and ElasticSearch, it's useful to have at least a high level understanding of how they work and how they are being used together.

RabbitMQ

RabbitMQis a popular message broker that can handle a high traffic of messages. Its role in our logging system is to simply receive all incoming logs and put them in appropriate queues, so other services can have access to these logs and process and/or store them in a central database.

RabbitMQ has 4 main entities:

  • publishers, which create the messages (in our case, it's ChiliLogger creating the logs);
  • exchanges, where publishers send the messages to;
  • queues, which receive just the messages from the exchange that are relevant to them.
  • consumers, which get messages from specific queues (in our case, that's Logstash/Elasticsearch)

explanation for RabbitMQ basic functioning

All messages are published to an exchange with a routing_key, which allows the exchange to know which queues should receive that message. RabbitMQ has a couple of possible exchange types and each one of them has a different way of distributing the messages among the queues. At Chiligum, we use only the topic type, the most flexible one and the one that can simulate all other types if needed.

In topic exchanges, the routing_key will be composed of keywords separated by dots ("."). Queues, on the other hand, will define which keywords they are interested at by defining their binding_keys. So a message with production.creatives.videos as routing_key would bedelivered to any queue with a matching binding_key of production.creatives.videos. Queues can use wildcards(*, #) in their binding keys. It's easier to understand it with the exemple from the RabbitMQ tutorials itself:

* can substitute for exactly one word. # can substitute for zero or more words.

In this example, we're going to send messages which all describe animals. The messages will be sent with a routing key that consists of three words (two dots). The first word in the routing key will describe a celerity, second a colour and third a species: "<celerity>.<colour>.<species>".

explanation for RabbitMQ topic excahnges

We created three bindings: Q1 is bound with binding key "*.orange.*" and Q2 with "*.*.rabbit" and "lazy.#". These bindings can be summarised as:

Q1 is interested in all the orange animals. Q2 wants to hear everything about rabbits, and everything about lazy animals.

A message with a routing key set to "quick.orange.rabbit" will be delivered to both queues. Message "lazy.orange.elephant" also will go to both of them. On the other hand "quick.orange.fox" will only go to the first queue, and "lazy.brown.fox" only to the second. "lazy.pink.rabbit" will be delivered to the second queue only once, even though it matches two bindings. "quick.brown.fox" doesn't match any binding so it will be discarded.

ElasticSearch

ElasticSearch is part of the so-called Elastic Stack. It is an open source database that offers powerful, fast querying of data. It is usually used with Logstash, also a tool of the Elastic Stack. Logstash can fetch or receive data from many different sources and can parse this data so it is in compliance with ElasticSearch data structures. At Chiligum, we create logs in JSON format and it is Logstash who converts it to Elasticsearch objects. Logstash can also work with RabbitMQ, creating queues and receiving data form them.

Putting It All Together

By now, perhaps it has already become clear how RabbitMQ and ElasticSearch are being used for Chiligum's logging system. ChiliLogger will create logs and publish them to a topic exchange in RabbitMQ with the appropriate routing_keys. RabbitMQ will distribute these logs to the queues created by Logstash instances. The distribution of messages will be according to the queues' binding_keys. Logstash instances will keep polling the queues, fetching messages, parsing them to Elasticsearch objects and storing them in Elasticsearch indexes. An Elasticsearch index is analogous to a SQS table, it's basically a collection of stored data.

video showing Chiligum's logging system in action

Installation

Add this line to your application's Gemfile:

gem 'chili_logger'

Create a initializer file and configure ChiliLogger passing all the relevant information. It is recommended to deactivate ChiliLogger when running tests:

# config/initializers/chili_logger.rb 
require 'chili_logger'

is_deactivated = Rails.env.test?

ChiliLogger.instance.config({
  deactivated: is_deactivated,
  log_env: Rails.env, # sets the log's env attribute
  log_layer: ENV['APPLICATION_NAME'], # sets the log's layer attribute
  server_url: ENV['SERVER_URL'], # used for log's ops_metadata attribute
  cloud_provider: ENV['CLOUD_PROVIDER'], # used for log's ops_metadata attribute
  msg_broker_name: :rabbitmq, # ChiliLogger's Message Broker
  msg_broker_config: {
    user: ENV['RABBIT_USER'],
    password: ENV['RABBIT_PASSWORD'],
    ip: ENV['RABBIT_IP'],
    port: ENV['RABBIT_PORT'],
    exchange_name: ENV['RABBIT_EXCHANGE'],
  },
  fallback_broker: :aws_sqs, # Chiligum's fallback option in case of Message Broker being down
  fallback_broker_config: {
    region: ENV['CHILI_LOGGER_SQS_HANDLER_REGION'],
    access_key_id: ENV['CHILI_LOGGER_SQS_HANDLER_KEY_ID'],
    secret_access_key: ENV['CHILI_LOGGER_SQS_HANDLER_SECRET_KEY'],
    queue_name: ENV['CHILI_LOGGER_SQS_HANDLER_QUEUE_NAME']
  }
})

The attributes log_env and log_layer set the fields 'env' and 'layer' in all logs that will be published by ChiliLogger.

When configuring ChiliLogger, you MUST set msg_broker_name and msg_broker_config. All logs are published to the configured message broker and, without it, ChiliLogger can't work. For the time being, only :rabbitmq is supported.

You ALSO MUST set fallback_broker and fallback_broker_config. This is the fallback option if the Message Broker is not available and, without it, ChiliLogger would break the application every time the Message Broker was down. For the time being, only :aws_sqs is supported.

Please note that if ChiliLogger tries to publish a log and both the configured Message Broker and the Error Handler are simultaneously down, the log will be discarded. This behavior makes sure logging problems never cause the app to break.

Basic Usage

The easiest way to use ChiliLogger is with the publish_instant_log method. It requires a hash with the following optional attributes: 

{
  desc: { # Hash
    type: 'transaction', # String,
    service: 'videos', # String
    action: 'create', # String
  },
  user: { 
    cognito_id: 100, # String || Fixnum || Bignum -> ChiliLogger converts cognito_id fields with these types to Strings
    email: '[email protected]', # String
    company_cognito_id: 88, # String || Fixnum || Bignum -> ChiliLogger converts company_cognito_id fields with these types to Strings
    company_name: 'Chiligum', # String
    admin_ghost_user: 420, # String || Fixnum || Bignum -> ChiliLogger converts admin_ghost_user with these types to Strings
  },
  main_content: { # Hash
    modified_records: {  # Hash
      "#{tablename}": [ # Array of Hashes
        { id: 42, title: 'Example video 1' },
        { id: 42, title: 'Example video 2' },
      ],
      "#{another_tablename}": [ # Array of Hashes
        { id: 42, title: 'Example banner 1' },
        { id: 42, title: 'Example banner 2' },
      ],
    },
    errors: [ # Array of Strings or Exception descendents -> ChiliLogger converts Exception descendents to Strings
      'first error',
      StandardError.new('second error')
    ]
  },
}

desc is used for setting the log's type, service, and action. env and layer were already set when ChiliLogger was initialized and configured. Only type, service, and action are accepted.

user will set the user data. Only cognito_id, email, company_cognito_id, company_name, and admin_ghost_user are accepted.

main_content will set the main information the log is concerned about. It only accepts modified_records or errors.

These fields must be set with the appropriate primitive types, as specified above. Not doing so may create invalid logs. ChiliLogger tries its best to enforce that all fields in a log will have consistent primitive types.

desc = { type: 'transaction', service: 'videos', action: 'create' }
agent = { user: { id: 88, email: '[email protected]'}, company: {id: 75, name: 'Chiligum' }}
main_content = { 
  modified_records: {
    videos: [{ id: 42, title: 'Lateralus' }]
  }
}

ChiliLogger.instance.publish_instant_log(desc, agent, main_content)
# publishes a json like this:
{
  "env": "development",
  "layer": "creatives",
  "type": "transaction",
  "service": "videos",
  "action": "create",
  "desc": "development.creatives.transaction.videos.create",
  "agent": { 
    "user": { 
      "id": 88, 
      "email": '[email protected]'
    }, 
    "company": {
      "id": 75, 
      "name": 'Chiligum' 
    }
  },
  "transaction": {
    "modified_records": {
      "videos": [{ "id": 42, "title": 'Lateralus' }]
    },
    "backtrace": [
      "app/views/dashboard/controllers/videos_controller.rb:17 in block 'create'"
    ]
  },
  "ops_metadata": {
    "server_url": "https://app.chiligumvideos.com"
  },
  "timestamp": "2020-06-30T18:08:59-03:00",
}

Passing desc, agent, and main_content is optional, since all of them have default values. This is so ChiliLogger is resiliant and doesn't break if any of these arguments is forgotten. But notice that their default values are not very descriptive and it results in low-quality (almost useless) logs:

ChiliLogger.instance.publish_instant_log
# publishes a json like this:
{
  "action": "not_specified",
  "layer": "creatives",
  "env": "development",
  "type": "not_specified",
  "service": "not_specified",
  "desc": "development.creatives.not_specified.not_specified.not_specified",
  "agent": "not_specified", 
  "not_specified": {},
    "backtrace": [
      "app/views/dashboard/controllers/videos_controller.rb:17 in block 'create'"
    ]
  },
  "ops_metadata": {
    "server_url": "https://app.chiligumvideos.com"
  },
  "timestamp": "2020-06-30T18:08:59-03:00",
}

Notice that ChiliLogger uses the Singleton pattern. So, to call its methods, you must first access the instance method. Calling ChiliLogger.new will return an error:

ChiliLogger.publish_instant_log(desc, agent, log)
# undefined method `publish_instant_log' for ChiliLogger:Class

ChiliLogger.new.publish_instant_log(desc, agent, log)
# NoMethodError: private method `new' called for ChiliLogger:Class

ChiliLogger.instance.publish_instant_log(desc, agent, log)
# works fine

Advanced Usage

It will often happen that the information needed for a log is distributed in many parts of the application and can't be accessed in a single moment nor in a single place of the code base. For instance, you may want to set the log's agent with information about the current_user that's only available in the Controllers Layer. And you might want to add data to the log every time a DB record is modified, which is easier to do in the Models Layer. For these use cases, ChiliLogger's publish_instant_log will not be suitable and you should use more advanced features.

ChiliLogger takes advantage of Ruby's Thread class and allows you to start a log and keep adding information to it during the current thread's lifespan. This is particularly useful when logging requests to a controller, since these requests will run from beginning to end in a single thread.

Once a log is started, it can be accessed and modified by using ChiliLogger's start_new_log method and current_log accessor.

Advanced Code Example

# controllers/videos_controller.rb
class VideosController
  def create
    desc = { type: 'transaction', service: 'videos', action: 'create' }
    agent = { user: current_user.as_json, company: current_user.as_json }
    current_log = ChiliLogger.instance.start_new_log(desc, agent) # Step One

    Video.create(title: 'Lateralus') # Step Two happens in the Video model

    current_log.publish # Step Three
  end
end

# models/video.rb
class Video < ApplicationRecord
  after_create :add_modified_record_to_log

  def add_modified_record_to_log
    current_log = ChiliLogger.instance.current_log
    modified_record = self.as_json

    current_log.add_modified_record(self.class.table_name, modified_record) # Step Two
  end
end

# resulting log (simplified)
{
  "env": "development",
  "layer": "creatives",
  "type": "transaction",
  "service": "videos",
  "action": "create",
  "desc": "development.creatives.transaction.videos.create",
  "agent": { 
    "user": { 
      "id": 88, 
      "email": '[email protected]'
    }, 
    "company": {
      "id": 75, 
      "name": 'Chiligum' 
    }
  },
  "transaction": {
    "modified_records": {
      "videos": [{ "id": 42, "title": 'Lateralus' }]
    },
    "backtrace": [
      "app/views/dashboard/controllers/videos_controller.rb:17 in block 'create'"
    ]
  },
  "ops_metadata": {
    "server_url": "https://app.chiligumvideos.com"
  },
  "timestamp": "2020-06-30T18:08:59-03:00",
}

Notice that the log is started in VideosController#create with some initial info about the agent user and the log description; following, the same log has its main_content customized in Video.add_modified_record_to_log, by accessing ChiliLogger's current_log and calling its add_modified_record method. And, afterwards, the same log is finished and published with current_log.publish, again in VideosController#create.

Check the Copy-Paste Snippets For Quick Logging section to see how this functionality can be used to quickly set an all-embracing logging system for your application.

Error Logging

The controller code above could be improved by adding some logic to log unexpected errors:

# controllers/videos_controller.rb
class VideosController
  def create
    desc = { type: 'transaction', service: 'videos', action: 'create' }
    agent = { user: current_user.as_json, company: current_user.as_json } # .as_json converts ActiveReacords into Hash
    current_log = ChiliLogger.instance.start_new_log(desc, agent)

    Video.create(title: 'Lateralus')

    current_log.publish

  rescue StandardError => error
    #changes log type and publishes it
    current_log.add_to_main_content({ error: error.as_json })
    current_log.overwrite_type('uncaught_error')
    current_log.publish
  end
end

A full list of methods for customizing a current_log is available

Customizing a Started Log

Once a log is started, its main attributes can be customized by accessing the current_log and calling one of its many customizing methods.

Accessing the current_log

current_log = ChiliLogger.instance.current_log
current_log.agent # returns currently set agent
current_log.overwrite_agent({ user: { name: 'new_agent' }) # sets new agent

agent

returns log's currently set agent

current_log.agent
# { user: { name: 'not_specified' } }

overwrite_agent

overwrites the currently set agent

current_log.agent
# { user: { name: 'not_specified' } }

current_log.overwrite_agent({ user: { name: 'new_agent' } })
current_log.agent
# { user: { name: 'new_agent' }

desc

returns currently set log's description. Notice that, for the time being, env and layer can't be overwritten, these description attributes can only be set during ChiliLogger's configuration

current_log.desc
# { type: 'not_specified', service: 'not_specified', action: 'not_specified' }

overwrite_type

overwrites the type attribute currently set in the log's description 

current_log.desc
# { type: 'not_specified', service: 'not_specified', action: 'not_specified' }

current_log.overwrite_type('transaction')
current_log.desc
# { type: 'transaction', service: 'not_specified', action: 'not_specified' }

overwrite_service

overwrites the service attribute currently set in the log's description 

current_log.desc
# { type: 'not_specified', service: 'not_specified', action: 'not_specified' }

current_log.overwrite_service('videos')
current_log.desc
# { type: 'not_specified', service: 'videos', action: 'not_specified' }

overwrite_action

overwrites the action attribute currently set in the log's description 

current_log.desc
# { type: 'not_specified', service: 'not_specified', action: 'not_specified' }

current_log.overwrite_action('delete')
current_log.desc
# { type: 'not_specified', service: 'not_specified', action: 'delete' }

overwrite_desc

overwrites the currently set log's description

current_log.desc
# { type: 'not_specified', service: 'not_specified', action: 'not_specified' }

current_log.overwrite_desc({ type: 'uncaught_error', action: 'create' })
current_log.desc
# { type: 'uncaught_error', service: 'not_specified', action: 'create' }

main_content

returns the currently set main_content

current_log.main_content
# { modified_records: {} }

overwrite_main_content

overwrites the currently set main_content

current_log.main_content
# { modified_records: {} }

current_log.overwrite_main_content({ meaning_of_life: 42 })
current_log.main_content
# { meaning_of_life: 42 }

add_to_main_content

merges hash with currently set main_content

current_log.main_content
# { modified_records: {} }

current_log.add_to_main_content({ meaning_of_life: 42 })
current_log.main_content
# { modified_records: {}, meaning_of_life: 42 }

modified_records

returns the modified_records stored in the main_content

current_log.modified_records
# {}

overwrite_modified_records

overwrites the modified_records stored in the main_content

current_log.modified_records
# {}

current_log.overwrite_modified_records({ tracks: [{ id: 88, title: 'Lateralus' }] })
current_log.modified_records
# { tracks: [{ id: 88, title: 'Lateralus' }] }

add_modified_record

merges hash with currently set modified_records

current_log.modified_records
# { tracks: [{ id: 88, title: 'Lateralus' }] }

current_log.overwrite_modified_records(
  { 
    tracks: [{ id: 89, title: "Hips Don't lie" }],
    videos: [{id: 42, title: 'Life Of Brian' }]
  }
)
current_log.modified_records
# { 
#   tracks: [{ id: 88, title: 'Lateralus' }, { id: 89, title: "Hips Don't lie" }],
#   videos: [{id: 42, title: 'Life Of Brian' }]
# }

clear_log_info

sets agent, desc, and main_content to their default values.

Copy-Paste Snippets for Quick Logging

Following are a series of snippets that can be copied and pasted to your project for quickly setting up some basic logging functionality.

Papertrail Optional Use

Please notice that the snippets in this section use the paper_trail gem for improving logs.

ChiliLogger works just fine without paper_trail. If you don't want to use paper_trail or if your application doesn't use ActiveRecords, you can skip the following code.

Papertrail allows us to keep a history of changes made to ActiveRecords entities, which is great for logging. To install and setup paper_trail, add the following code:

// optional code if you want to use Papertrail to enrich logs
$ bundle add paper_trail
$ bundle install
$ bundle exec rails generate paper_trail:install
$ bundle exec rake db:migrate

and then:

# optional code if you want to use Papertrail to enrich logs

# models/application_record.rb
class ApplicationRecord < ActiveRecord::Base
  self.abstract_class = true

  has_paper_trail # add this line!
end

Logging Transactions

Logging Rake Tasks

A Note About ActiveRecords

Coverage