joppot

The program absolutely runs in copy paste

Server

Collect Rails 5 production.log with td-agent

投稿日:2017年4月12日 更新日:

Pocket


Abstract

Hello everybody It’s me candle.
In this article I will show you how to collect rails 5 production.log with td-agent.
Rails 5 was changed log format and it cause some problem.
I will solve it and explain.

relational article

If you are using rails 4 please refer to the following article.

td-agentでRails 4のproduction.logを取得する

Precondition

You can work ruby on rails in production mode
Before read this article you setup the rails production environment such as webrick, apache, puma and nginx.

You already installed td-agent or fluentd.
You need td-agent or fluentd. It is installed on the ruby on rails server.

SPONSORED LINK

Change the rails log format

This is a default rails 5 production format.

There are two places where Rails 5 log format is different from Rails 4.
Rails 5 log format added request id like this.

[5865421e-16ac-4ced-8a64-8153a981e583]

For rails logs, multiple lines of logs are output, such as status, which pages, what parameters are, even for one access.
The request ID is very useful and the same request ID is displayed during the 1 access so that you can see where the same access.

Another thing is not good news for td-agent user. The FATAL error message is output separate each line.

F, [2017-04-02T15:30:34.412677 #59749] FATAL — : [ac9e209a-bec…]
F, [2017-04-02T15:30:34.412796 #59749] FATAL — : [ac9e209a-bec…] NoMethodError (undefined method `each’ for nil:NilClass):
F, [2017-04-02T15:30:34.412847 #59749] FATAL — : [ac9e209a-bec…]
F, [2017-04-02T15:30:34.412897 #59749] FATAL — : [ac9e209a-bec…] app/controllers/pages_controller.rb:6:in `about’

In fact, in spite of one error, every new line in the error message will be written in the log as a another error.

For example, if you make td-agent and slack cooperate to notify when FATAL error is occured, you get notified for each new line despite one error.

In this article, override the function that displays the error log and change it to output of log like Rails 4.
Of course, if it is ok to save FATAL error messages as separate logs, you can skip the next chapter.

Chnage the Fatal error log format

Fortunately it is not difficult to change the part of Fatal message.
Change the log_error function as Rails 4 format.

In addition, if we also delete the newline character, it will be easier for fluentd’s processing.

Open the config/environment.rb in rails project and write it

module ActionDispatch
  class DebugExceptions
    def log_error(request, wrapper)
      logger = logger(request)
      return unless logger

      exception = wrapper.exception

      trace = wrapper.application_trace
      trace = wrapper.framework_trace if trace.empty?

      ActiveSupport::Deprecation.silence do
        message = "#{exception.class} (#{exception.message}):"
        message << exception.annoted_source_code.to_s if exception.respond_to?(:annoted_source_code)
        message << "  " << trace.join("\n  ")
        logger.fatal("#{message}")
      end
    end
  end
end

Let’s restart the server and see how the FATAL error log has changed.

The FATAL error message is included in to one line like this sample.

F, [2017-04-02T16:34:38.573875 #60108] FATAL — : [e9287f69-3a2d-47a0-a556-c5789141239d] NoMethodError (undefined method `each’ for nil:NilClass): app/controllers/pages_controller.rb:6:in `about’

Error log setting is over.

Do not display View logs

The following is a code without any change from the default log format.

class Logger::Formatter
  def call(severity, time, progname, msg)
    format = "%s, [%s #%d] %5s -- %s: %s\n"
    format % [severity[0], "#{time.strftime('%Y-%m-%dT%H:%M:%S')}.#{'%06d' % time.usec.to_s}", $$, severity, progname, msg2str(msg)]
  end
end

In rails production log it outputs view information too.
Since this information is wasteful, it should not be left in the log.
This is the part of log.

I, [2017-03-24T06:19:15.314646 #5689] INFO — : Rendered users/shared/_links.html.haml (0.5ms)
I, [2017-03-24T06:19:15.315840 #5689] INFO — : Rendered users/registrations/new.html.haml within layouts/application (6.6ms)
I, [2017-03-24T06:19:15.318778 #5689] INFO — : Rendered layouts/_header.html.haml (0.6ms)
I, [2017-03-24T06:19:15.320581 #5689] INFO — : Rendered layouts/_footer.html.haml (0.8ms)

It is ok if you don’t change that or not.

Open the config/environment.rb

Change the format like this.
If you are using erb please change “.haml” part to “.erb”.

class Logger::Formatter
  def call(severity, time, progname, msg)
    if !msg.include?('.haml')
      format = "%s, [%s #%d] %5s -- %s: %s\n"
      format % [severity[0], "#{time.strftime('%Y-%m-%dT%H:%M:%S')}.#{'%06d' % time.usec.to_s}", $$, severity, progname, msg2str(msg)]
    end
  end
end

Setting of rails is over.

Preparing to get rails log with td-agent

Alright, let’s prepare for td-agent side.

My rails and td-agent environment is like this.
Td-agent is running with CentOS 6.5.
Rails application is running on the unicorn + nginx.
Please prepare those servers environment.

Set up td-agent

In rails 4 production log is that Fatal errors are displayed over multiple lines. However, since the error_log function was overridden, the FATAL error message is gathered in one line. So you can write td-agent setting as a simple

<source>
  @type tail
  path /usr/share/nginx/alice5/log/production.log
  tag rails.production
  pos_file /var/log/td-agent/rails.production.pos
  format /^(?<log_initial>.*), [(?<date>d{1,4}-d{1,2}-d{1,2}Td{1,2}:d{1,2}:d{1,2}.d{1,6}) (?<process_id>[^ ]*)] *(?<log_level>[^ ]*) -- : [(?<request_id>[^ ]*)] (?<message>[^']*[^]]*)/
</source>

<match rails.production>
  @type stdout
</match>

With the “path” reference the production.log in the log folder of the rails project.
Please rewrite the reference path to your environment.

“tag rails.production” tagged a collected log.

With the “pos_file /var/log/td-agent/rails.production.pos” specifies the location of temporary files.

In the “format” matches the format of rails 5 production.log.

” directive catch the log and display it.

This is the setting for td-agent to get rails log.

Getting log and check it

Restart the td-agent server.

sudo serice td-agent restart

Lauch the rails application in production.
Let’s access.

The td-agent log is output to the following location.

/var/log/td-agent/td-agent.log

Check with the tail command.

sudo tail -f /var/log/td-agent/td-agent.log

This is the log.

The most important thing is the part of “FATAL”.

2017-04-02 08:42:04.485309539 +0000 rails.production: {“log_initial”:”F”,”date”:”2017-04-02T08:42:00.564377″,”process_id”:”#11178″,”log_level”:”FATAL”,”request_id”:”44099c89-5e55-49b9-9d1f-0f18308133d6″,”message”:”NoMethodError (undefined method `each’ for nil:NilClass): app/controllers/pages_controller.rb:6:in `about'”}

The messages are gathered to one.

Conclusion

How about you, did you get it well?
I think that it is best not to edit the log format of rail as much as possible.
However, I had to change it in the form of FATAL error message.
If I get more good ways than this in the future I would like to change it.

スポンサードリンク

If you think this article is good, share it please

-Server
-, ,

執筆者:


comment

Your email address will not be published. Required fields are marked *

関連記事

Monitor the memory state of ec2 with watch and free command

English 日本語 Abstract Hello everyone, It’s candle. In this time, I will show you how to monitor ec2 memory in real time. EC2 server of t2.micro has only 1GB of memory, If you run composer, rails, mysql on it, memory may be barely. It is useful if you can monitor the memory and tune the server. Precondition EC2 server

Setup of td-agent-ui and operation check

English 日本語 Abstract Hello everyone, It’s candle. In this time, I will show you how to set up td-agent-ui and operation check. Td-agent is easier than fluentd to operate on the server. Precondition Td-agent is installed Please refer to the following article when building td-agent to Centos 6.5. Build up a td-agent server on centos 6.5 For EC2, here Build up td-agent server on the EC2 of aws

Build up a td-agent server on centos 6.5

English 日本語 Abstract Hello everyone, It’s candle. In this time, we build up a td-agent server on the centos 6.5. Td-agent is service based on fluentd. It daemonizes fluentd and creates a GUI. Premise You have Centos 6.5 server. I use Centos 6.5 on the vagrant for explanation.

Build up td-agent server on the EC2 of aws

English 日本語 Abstract Hello everyone, It’s candle. In this time we will build up td-agent environment on the ec2. Precondition You have a EC2.

Install only mysql command for RDS in EC2

Abstract Hello everyone it’s me candle. This topic is a little thing but I note to self. If we use RDS, we don’t need Mysql server in the EC2. You may want to install only the mysql command. I will explain it. Precondition You use EC2 and RDS

Profile


I work in the venture company as a CTO. I start to write program in University, first I learned java, C++ and PHP. In the company, I'm developing web services by Rails. I do like to automation.

スポンサードリンク

Archives