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
- How it Works
- Installation
- Basic Usage
- Advanced Usage
- Code Example
- Error Logging
- Customizing a Started Log
- Accessing the current_log
- user
- update_user
- desc
- update_type
- update_service
- update_action
- update_desc
- main_content
- update_main_content
- add_to_main_content
- modified_records
- update_modified_records
- add_modified_record
- clear_log_info
- Republishing Unpublished Logs
- Snippets For Quicker Logging
- Coverage
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
Every time we use ChiliLogger to publish a log, it will try to publish it to what has been configured as its msg_broker
. If the msg_broker is down or some other unexpected error occurs, ChiliLogger will send the log and error message to what has been configured as its fallback_broker
. This way, no logs are lost and ChiliLogger can later try to republish these unpublished logs.
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. For this reason, it is important to use a main message broker and a fallback broker with high availability.
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",
"ghost_user_cognito_id": "not_specified"
},
"transaction": {
"modified_records": {
"videos": [{ "id": 42, "title": 'Lateralus' }],
"gallery_tags": [{ "id": 50 }, { "id": 51 }, { "id": 52 }],
"tags": [{ "id": 23, "name": "tool" }]
},
"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...log
is used to record steps of processing flowing among the platform layers, these records help debug and find errors.
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.
It is an object with that accepts the folowwing attributes:
modified_records
, listing all tables modified and the records themselves;errors
, listing errors found during the transaction and will usually be an empty array if the transaction was successful;backtrace
, automatically created by the gem itself and showing the backtrace of the transaction and its processing;
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)
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>
".
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.
Installation
Add this line to your application's Gemfile:
gem 'chili_logger'
Basic Initialization
ChiliLogger currently relies on aws-sdk and, for that reason, requires you to intall and configure it in your machine.
To configure ChiliLogger, create a initializer file and configure it by passing all the relevant data. 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, usually it is set to 'aws' or nil
})
The attributes log_env
and log_layer
set the fields 'env' and 'layer' in all logs that will be published by ChiliLogger. server_url
and cloud_provided
are not mandatory, but they provide additional ops data and are recommended when running in staging or production environments.
Customizing the Message Brokers
Usually, we want to allow the gem to use the default configuration for the Main Message Broker and the Fallback Message Broker. However, if you need to customize it for testing or special cases, you can do it by passing the appropriate data to ChiliLogger when initializing it:
# 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; optional, defaults to :rabbitmq
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, # ChiliLogger's fallback option in case of Message Broker being down; optional, defaults to :aws_sqs
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']
}
})
For the time being, only :rabbitmq
is supported as the msg_broker_name
and only :aws_sqs
is supported as the fallback_broker
.
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.
Overwriting RabbitMQ's routing_key
The routing_key for all messages sent to rabbit will be created based on the description tag of the log. But, sometimes, specially when testing, you may want to force all messages to be sent with a hardcoded routing_key. In those cases, you can add an optional field to the msg_broker_config: routing_key_overwriter
.
ChiliLogger.instance.config({
...
msg_broker_name: :rabbitmq,
msg_broker_config: {
user: ENV['RABBIT_USER'],
password: ENV['RABBIT_PASSWORD'],
ip: ENV['RABBIT_IP'],
port: ENV['RABBIT_PORT'],
exchange_name: ENV['RABBIT_EXCHANGE'],
routing_key_overwriter: 'a.hardcoded.routing.key'
},
...
})
Basic Usage
publish_instant_log params
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
ghost_user_cognito_id: 420, # String || Fixnum || Bignum -> ChiliLogger converts ghost_user_cognito_id 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 ghost_user_cognito_id
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. Because of that, ChiliLogger tries its best to enforce that all fields in a log will have consistent primitive types.
publish_instant_log usage example
desc = { type: 'transaction', service: 'videos', action: 'create' }
user = {
cognito_id: 88,
email: '[email protected]',
company_cognito_id: 75,
company_name: "Chiligum Creatives",
ghost_user_cognito_id: 55
},
main_content = {
modified_records: {
# notice we have a key 'videos' (the SQS tablename) pointing to an array of hashes
videos: [{ id: 42, title: 'Lateralus' }]
}
}
ChiliLogger.instance.publish_instant_log(desc: desc, user: user, main_content: main_content)
# publishes a json like this:
{
"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",
"ghost_user_cognito_id": "55"
},
"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",
}
publish_instant_log default argument values
Passing desc
, user
, 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",
"user": {
"cognito_id": 'not_specified',
"email": 'not_specified',
"company_cognito_id": 'not_specified',
"company_name": 'not_specified',
"ghost_user_cognito_id": '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",
}
ChiliLogger's Singleton pattern
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(deasc: desc, user: user, main_content: main_content)
# undefined method `publish_instant_log' for ChiliLogger:Class
ChiliLogger.new.publish_instant_log(deasc: desc, user: user, main_content: main_content)
# NoMethodError: private method `new' called for ChiliLogger:Class
ChiliLogger.instance.publish_instant_log(deasc: desc, user: user, main_content: main_content)
# 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 user 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' }
user = { cognito_id: 88, email: '[email protected]', company_cognito_id: 75,
company_name: "Chiligum Creatives", ghost_user_cognito_id: 55 },
current_log = ChiliLogger.instance.start_new_log(desc: desc, user: user) # 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",
"user": {
"cognito_id": 'not_specified',
"email": 'not_specified',
"company_cognito_id": 'not_specified',
"company_name": 'not_specified',
"ghost_user_cognito_id": 'not_specified'
},
"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 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 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' }
user = { cognito_id: 88, email: '[email protected]', company_cognito_id: 75,
company_name: "Chiligum Creatives", ghost_user_cognito_id: 55 },
current_log = ChiliLogger.instance.start_new_log(desc: desc, user: user)
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.update_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.user # returns currently set user
current_log.update_user(cognito_id: '42', company_name: 'Chiligum') # updates user data
user
returns log's currently set user
current_log.user
# { cognito_id: 'not_specified', email: 'not_specified', company_cognito_id: 'not_specified',
# company_name: 'not_specified', ghost_user_cognito_id: 'not_specified' }
update_user
updates the currently set user
current_log.user
# { cognito_id: 'not_specified', email: 'not_specified', company_cognito_id: 'not_specified',
# company_name: 'not_specified', ghost_user_cognito_id: 'not_specified' }
current_log.update_user(email: 'new_email')
current_log.user
# { cognito_id: 'not_specified', email: 'new_email', company_cognito_id: 'not_specified',
# company_name: 'not_specified', ghost_user_cognito_id: 'not_specified' }
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' }
update_type
updates the type attribute currently set in the log's description
current_log.desc
# { type: 'not_specified', service: 'not_specified', action: 'not_specified' }
current_log.update_type('transaction')
current_log.desc
# { type: 'transaction', service: 'not_specified', action: 'not_specified' }
update_service
updates the service attribute currently set in the log's description
current_log.desc
# { type: 'not_specified', service: 'not_specified', action: 'not_specified' }
current_log.update_service('videos')
current_log.desc
# { type: 'not_specified', service: 'videos', action: 'not_specified' }
update_action
updates the action attribute currently set in the log's description
current_log.desc
# { type: 'not_specified', service: 'not_specified', action: 'not_specified' }
current_log.update_action('delete')
current_log.desc
# { type: 'not_specified', service: 'not_specified', action: 'delete' }
update_desc
updates the currently set log's description
current_log.desc
# { type: 'not_specified', service: 'not_specified', action: 'not_specified' }
current_log.update_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: {}, errors: [] }
update_main_content
updates the currently set main_content
current_log.main_content
# { modified_records: {}, errors: [] }
new_content = {
modified_records: {
'videos' => [{ title: 'Lateralus', id: 42 }]
}
}
current_log.update_main_content(new_content)
current_log.main_content
# {
# modified_records: {
# 'videos' => [{ title: 'Lateralus', id: 42 }]
# },
# errors: []
# }
add_to_main_content
merges hash with currently set main_content
current_log.main_content
# { modified_records: {}, errors: ['err1', 'err2'] }
current_log.add_to_main_content(errors: ['err50'])
current_log.main_content
# { modified_records: {}, errors: ['err1', 'err2', 'err50'] }
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
# { tracks: [{ id: 87, title: 'Hips Dont Lie' }] }
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. Notice it receives two arguments: the tablename
and the record
itself;
current_log.modified_records
# { tracks: [{ id: 88, title: 'Lateralus' }] }
current_log.add_modified_records('tracks', { id: 89, title: "Hips Don't lie" })
current_log.modified_records
# {
# tracks: [{ id: 88, title: 'Lateralus' }, { id: 89, title: "Hips Don't lie" }],
# }
current_log.add_modified_records('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' }]
# }
errors
returns the errors stored in the main_content
current_log.errors
# []
overwrite_errors
overwrites the errors stored in the main_content
current_log.errors
# ['err1', 'err2', 'err3']
current_log.overwrite_errors(['err500'])
current_log.errors
# ['err500']
add_error
merges hash with currently set errors
current_log.errors
# ['err1', 'err2', 'err3']
current_log.add_error('err400')
current_log.errors
# ['err1', 'err2', 'err3', 'err400']}
clear_log_info
sets user, desc, and main_content to their default values.
Republishing Unpublished Logs
This functionality was introduced in version 0.1.2 of ChiliLogger. If you are using ChiliLogger 0.0.12 or below, you must first upgrade it.
As previously explained, if logs can't be published to the main message broker
, then these unpublished logs will be sent to the fallback broker
. We can easily tell ChiliLogger to try and republish these logs any time, just by running the following:
ChiliLogger.instance.republish_unpublished_logs
When running the above snippet, ChiliLogger will fetch the unpublished logs and try to republish them to the main message broker
. If the main message broker is still unavailable, ChiliLogger will once again send the logs to fallback broker
.
Snippets for Quicker Logging
Following is a series of snippets for quickly setting up some basic logging functionality. Please notice that the snippets in this section use the paper_trail gem for improving logs. Its use is optional, but recommended.
Papertrail Optional Use
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
If your controllers have a current_user, it usually won't be accessible in the models. When implementing logs, though, it is a behaviour you might be interested in, so you can log changes to the DB knowing who was the user responsible for that change. PaperTrail has a feature called whodunnit
, which is used precisely for this purpose.
# controllers/application_controller.rb
class ApplicationController < ActionController::Base
# sets papertrail Whodunit based on user defined in user_for_paper_trail
before_action :set_paper_trail_whodunnit
# customizes method implemented by PaperTrail and that sets PaperTrail.request.whodunnit
# PaperTrail.request.whodunnit will be available in all parts of application while a request is being processed
def user_for_paper_trail
current_user
end
end
Logging Transactions in HTTP Requests
Transactions happen in two main layers of an application: the controllers handling the request and the models persisting data. If your application has an ApplicationController from which all other controllers inherit, and also an ApplicationRecord from which all models inherit, we can quickly set standardized logs for transactions and errors.
Controllers Logging Logic
Just add the following code to your ApplicationController:
# controllers/application_controller.rb
class ApplicationController < ActionController::Base
before_action :start_new_log
rescue_from StandardError, with: :publish_error_log
after_action :publish_log
def start_new_log
table_name = self.class.name.split('::').last.gsub('Controller', '').underscore
# action_name is available in Rails apps, Sinatra apps may need some other solution
log_action = action_name == 'destroy' ? 'delete' : action_name
desc ||= log_description('transaction', table_name, log_action)
user = log_user
ChiliLogger.instance.start_new_log(desc: desc, user: user)
end
# publishes transaction log with the main infos about the request
def publish_log
# only publish log if current log had modified_records added to it, so we don't clutter logs with index requests
return if ChiliLogger.instance.current_log.modified_records.empty?
ChiliLogger.instance.current_log.publish
end
# if unexpected errors happen, will change log type and publish it for debugging/audit
def publish_error_log(error)
current_log = ChiliLogger.instance.current_log
current_log.add_error(error)
current_log.update_type('uncaught_error')
current_log.publish
raise error
end
private
def log_description(type, service, action)
{ type: type, service: service, action: action }
end
# customize according to your app's schema
def log_user
return {} unless current_user
# use .where instead of .find, because .find raises error if no record is found
multi_user_record = MultiUser::User.where(external_id: current_user&.cognito_id).first
log_user = {
email: current_user&.email,
cognito_id: multi_user_record&.external_id,
company_name: current_user&.company&.name,
company_cognito_id: multi_user_record&.organization&.id
}
log_user.merge!(ghost_user_cognito_id: admin_ghost_user&.cognito_id) # if app has admins that can log as other users
end
end
Notice that start_new_log
will set the log's service and action based on the controller name and the method being called. So if VideosController has its create method called, it would generate a log with service="videos" and action="create". Individual controllers and methods can be customized by using the current_log accessors.
For example, suppose we would like the GalleryFilesController to generate custom logs with service='gallery' and we would like GalleryFilesController#find_files to define action='filter'. We could do the following:
# app/controllers/gallery_files.rb
class GalleryFilesController < ApplicationController
before_action :overwrite_log_service
def find_files
ChiliLogger.instance.current_log.update_action('filter')
# method's usual code...
end
private
# customizes logs created by ApplicationController's start_new_log method
def overwrite_log_service
ChiliLogger.instance.current_log.update_service('gallery')
end
end
Models Logging Logic
The code above implements automatic logs for requests made to controllers. We can further improve the logs being created by adding the DB records that were modified during the request:
class ApplicationRecord < ActiveRecord::Base
self.abstract_class = true
after_create -> { add_modified_record_to_log('create') }, on: :create
after_update -> { add_modified_record_to_log('update') }, on: :update
before_destroy -> { add_modified_record_to_log('destroy') }, on: :destroy
# enriches logs by automatically adding modified_records to them
def add_modified_record_to_log(action_verb, modified_record = self)
# only adds to log if record was created, changed or destroyed
return if !new_record? && !saved_changes? && action_verb != 'destroy'
current_log = ChiliLogger.instance.current_log
current_log.update_type('transaction_error') unless modified_record.errors..empty?
current_log.add_modified_record(self.class.table_name, modified_record.to_denormalized_hash)
end
# ChiliLogger requires modified_records to be hashes.
# This method converts ActiveRecords instances to hashes and adds some extra useful data
def to_denormalized_hash(record_hash = as_json)
record_hash[:last_changes] = saved_changes
record_hash[:errors] = errors
record_hash
end
end
The code above will add all modified records to the transaction logs. We implement a to_denormalized_hash
method, which converts the ActiveRecord isntance to a hash, as ChiliLogger requires. This method can be customized in individual models, to generate logs with even more information (for instance, denormalizing the main ActiveRecords relations):
# app/models/banner.rb
class Banner < ApplicationRecord
# customizes inherited ApplicationRecord's method, denormalizing the record's main relations
def to_denormalized_hash(record_hash = as_json)
relations = Banner.includes(:campaign)
.includes(template: %i[category template_collection])
.find(id)
record_hash[:campaign] = relations.campaign.as_json
record_hash[:template] = relations.template.as_json
record_hash[:template][:category] = relations.template.category.as_json
record_hash[:template][:template_collection] = relations.template.template_collection.as_json
super(record_hash) # calls ActiveRecords's to_denormalized_hash
end
end
Logging Rake Tasks
When logging transactions made in tasks, we have three main concerns: logging uncaught errors in the task, logging transactions performed by the task and log whether the task is up and running, for monitoring.
Logging Uncaught Task Errors
For this, we must create a standardized way of handling task errors. The best wayto do it is with a monkey-patch to rake, by creating the following file:
# config/initializers/task.rb
require 'rake/task'
module Rake
class Task
alias :original_execute :execute
# customizes the execute method of Rake::Task
def execute(args=nil)
begin
# start storing default log infos for rake tasks before they even begin
log_desc = { log_type: 'error', service: 'automated_task', action: 'uncaught_error' }
log_user = { email: 'automated_task', cognito_id: 'automated_task' }
ChiliLogger.instance.start_new_log(desc: log_desc, user: log_user)
original_execute(args)
rescue StandardError => error
current_log = ChiliLogger.instance.current_log
current_task = Rake.application.top_level_tasks.first
current_log.update_service(current_task.split(':').first)
current_log.update_action(current_task.split(':').last)
current_log.add_error(error.inspect)
current_log.update_type('uncaught_error')
current_log.publish
raise error
end
end
end
end
Logging Transactions in Tasks
Unfortunately, for the time being, we still haven't found a practical way to log all Task transactions with minimal setup. The way most of our tasks are implemented - as infinite loops - requires us to add logging logic to each and every task, by doing so:
# lib/tasks/example_task.rake
namespace :excel do
task validation: :environment do
loop do
# start storing infos for validation log
transaction_desc = { type: 'transaction', service: 'excel', action: 'validation' }
log_user = { email: 'automated_task', cognito_id: 'automated_task'
current_log = ChiliLogger.instance.start_new_log(desc: log_desc, user: log_user)
usual task code...
# only publish log if current log had modified_records added to it - so we don't clutter DB with meaningless logs
current_log.publish unless current_log.modified_records.empty?
sleep 5
end
end
Until we come up with a better solution, this will have to be done to each and every task of interest. Notice that the snippet above assumes you have edited the models to enrich logs with modified_records.
Logging Heartbeats in Tasks
Besides monitoring transactions and unexpected errors, it is also important to monitor whether all main parts of an application are up and running. For servers, we do that by pinging specific endpoints to see if the server is up and responding. Tasks pose a different problem, since they have no endpoint we can ping. Besides, a task maybe up and with a 'running' status, but being stuck all the same and not processing new data. For that reason, we use ChiliLogger to monitor tasks' healht.
Unfortunately, due to the way most of our tasks are implemented - as infinite loops - we must add logging logic to each and every task, by doing so:
# lib/tasks/example_task.rake
namespace :excel do
task validation: :environment do
loop do
heartbeat_desc = { type: 'monitoring', service: 'excel', action: 'validation' }
log_user = { email: 'automated_task', cognito_id: 'automated_task'
ChiliLogger.instance.publish_instant_log(desc: heartbeat_desc, user: log_user)
usual task code...
sleep 5
end
end
Coverage
ChiliLogger keeps a coverage report, showing what kinds of logs are being created. This can be usefull to see whether all important points of an application are being satisfactorily monitored and also to have an overview of how these logs description tags are looking like. This coverage report can be found in app_root/log/chili-logger-coverage.yml
. It is an YAML file with 4 dimensions:
- first dimension: type;
- second dimension: service;
- third dimension: action;
- fourth dimension: an array with the backtrace of the last created log to a given type, service and action combination;
transaction: #log's type
videos: # log's service
create: # log's action
- "backtrace_path_1" # backtrace for transaction.videos.create
- "backtrace_path_2"
- "backtrace_path_3"
update: # log's action
- "backtrace_path_1" # backtrace for transaction.videos.update
- "backtrace_path_2"
- "backtrace_path_3"
banners:
create: # log's action
- "backtrace_path_1" # backtrace for transaction.banners.create
- "backtrace_path_2"
- "backtrace_path_3"
accept: # log's action
- "backtrace_path_1" # backtrace for transaction.banners.accept
- "backtrace_path_2"
- "backtrace_path_3"
uncaught_error: #log's type
gallery: # log's service
index: # log's action
- "backtrace_path_1" # backtrace for uncaught_error.gallery_index
- "backtrace_path_2"
- "backtrace_path_3"
monitoring: #log's type
campaigns: # log's service
validate_sheet: # log's action
- "backtrace_path_1" # backtrace for monitoring.campaigns.validate_sheet
- "backtrace_path_2"
- "backtrace_path_3"