Railsアプリで puts, logger コマンドを実行した時の log / 標準出力 について

はじめに

Railsアプリでputs,loggerコマンドを実行した時の log / 標準出力 について記録しておきます。

確認したこと

• production/development/testモードでputs,loggerコマンドを実行した時に log / 標準出力 されるか
• puts,loggerコマンドの結果が log / 標準出力 にどのようなフォーマットで出力されるか

注意点

動作確認はRails 5.1.4のデフォルト設定（rails newで生成されるconfig/production.rb）で実施しました。

Controller

log / 標準出力させるためにControllerへ下記のコードを記述しました。

puts         'LOGGER TEST >>> puts'
logger.debug 'LOGGER TEST >>> debug'
logger.info  'LOGGER TEST >>> info'
logger.warn  'LOGGER TEST >>> warn'
logger.error 'LOGGER TEST >>> error'
logger.fatal 'LOGGER TEST >>> fatal'

結果

logファイルとpumaの標準出力を確認しました。

production

コマンド	logファイル	pumaの標準出力
puts	×	○
logger.debug	○	×
logger.info	○	×
logger.warn	○	×
logger.error	○	×
logger.fatal	○	×

○：出力される / ×：出力されない

logファイル

log/test.log

I, [2017-09-23T19:33:29.881121 #57590]  INFO -- : [7fb1db69-5082-4562-bf4e-5c255899bdff] Started GET "/test/index" for 127.0.0.1 at 2017-09-23 19:33:29 +0900
I, [2017-09-23T19:33:29.883079 #57590]  INFO -- : [7fb1db69-5082-4562-bf4e-5c255899bdff] Processing by TestController#index as HTML
D, [2017-09-23T19:33:29.892648 #57590] DEBUG -- : [7fb1db69-5082-4562-bf4e-5c255899bdff] LOGGER TEST >>> debug
I, [2017-09-23T19:33:29.892823 #57590]  INFO -- : [7fb1db69-5082-4562-bf4e-5c255899bdff] LOGGER TEST >>> info
W, [2017-09-23T19:33:29.893043 #57590]  WARN -- : [7fb1db69-5082-4562-bf4e-5c255899bdff] LOGGER TEST >>> warn
E, [2017-09-23T19:33:29.893100 #57590] ERROR -- : [7fb1db69-5082-4562-bf4e-5c255899bdff] LOGGER TEST >>> error
F, [2017-09-23T19:33:29.893142 #57590] FATAL -- : [7fb1db69-5082-4562-bf4e-5c255899bdff] LOGGER TEST >>> fatal
I, [2017-09-23T19:33:29.898447 #57590]  INFO -- : [7fb1db69-5082-4562-bf4e-5c255899bdff]   Rendering test/index.html.erb within layouts/application
I, [2017-09-23T19:33:29.899237 #57590]  INFO -- : [7fb1db69-5082-4562-bf4e-5c255899bdff]   Rendered test/index.html.erb within layouts/application (0.6ms)
I, [2017-09-23T19:33:29.900741 #57590]  INFO -- : [7fb1db69-5082-4562-bf4e-5c255899bdff] Completed 200 OK in 18ms (Views: 5.3ms)

pumaの標準出力

LOGGER TEST >>> puts

設定ファイル

config/environments/production.rb

Rails.application.configure do
  # Settings specified here will take precedence over those in config/application.rb.

  # Code is not reloaded between requests.
  config.cache_classes = true

  # Eager load code on boot. This eager loads most of Rails and
  # your application in memory, allowing both threaded web servers
  # and those relying on copy on write to perform better.
  # Rake tasks automatically ignore this option for performance.
  config.eager_load = true

  # Full error reports are disabled and caching is turned on.
  config.consider_all_requests_local       = false
  config.action_controller.perform_caching = true

  # Attempt to read encrypted secrets from `config/secrets.yml.enc`.
  # Requires an encryption key in `ENV["RAILS_MASTER_KEY"]` or
  # `config/secrets.yml.key`.
  config.read_encrypted_secrets = true

  # Disable serving static files from the `/public` folder by default since
  # Apache or NGINX already handles this.
  config.public_file_server.enabled = ENV['RAILS_SERVE_STATIC_FILES'].present?

  # Compress JavaScripts and CSS.
  config.assets.js_compressor = :uglifier
  # config.assets.css_compressor = :sass

  # Do not fallback to assets pipeline if a precompiled asset is missed.
  config.assets.compile = false

  # `config.assets.precompile` and `config.assets.version` have moved to config/initializers/assets.rb

  # Enable serving of images, stylesheets, and JavaScripts from an asset server.
  # config.action_controller.asset_host = 'http://assets.example.com'

  # Specifies the header that your server uses for sending files.
  # config.action_dispatch.x_sendfile_header = 'X-Sendfile' # for Apache
  # config.action_dispatch.x_sendfile_header = 'X-Accel-Redirect' # for NGINX

  # Mount Action Cable outside main process or domain
  # config.action_cable.mount_path = nil
  # config.action_cable.url = 'wss://example.com/cable'
  # config.action_cable.allowed_request_origins = [ 'http://example.com', /http:\/\/example.*/ ]

  # Force all access to the app over SSL, use Strict-Transport-Security, and use secure cookies.
  # config.force_ssl = true

  # Use the lowest log level to ensure availability of diagnostic information
  # when problems arise.
  config.log_level = :debug

  # Prepend all log lines with the following tags.
  config.log_tags = [ :request_id ]

  # Use a different cache store in production.
  # config.cache_store = :mem_cache_store

  # Use a real queuing backend for Active Job (and separate queues per environment)
  # config.active_job.queue_adapter     = :resque
  # config.active_job.queue_name_prefix = "rails-logger_#{Rails.env}"
  config.action_mailer.perform_caching = false

  # Ignore bad email addresses and do not raise email delivery errors.
  # Set this to true and configure the email server for immediate delivery to raise delivery errors.
  # config.action_mailer.raise_delivery_errors = false

  # Enable locale fallbacks for I18n (makes lookups for any locale fall back to
  # the I18n.default_locale when a translation cannot be found).
  config.i18n.fallbacks = true

  # Send deprecation notices to registered listeners.
  config.active_support.deprecation = :notify

  # Use default logging formatter so that PID and timestamp are not suppressed.
  config.log_formatter = ::Logger::Formatter.new

  # Use a different logger for distributed setups.
  # require 'syslog/logger'
  # config.logger = ActiveSupport::TaggedLogging.new(Syslog::Logger.new 'app-name')

  if ENV["RAILS_LOG_TO_STDOUT"].present?
    logger           = ActiveSupport::Logger.new(STDOUT)
    logger.formatter = config.log_formatter
    config.logger    = ActiveSupport::TaggedLogging.new(logger)
  end

  # Do not dump schema after migrations.
  config.active_record.dump_schema_after_migration = false
end

development

コマンド	logファイル	pumaの標準出力
puts	×	○
logger.debug	○	○
logger.info	○	○
logger.warn	○	○
logger.error	○	○
logger.fatal	○	○

○：出力される / ×：出力されない

logファイル

log/development.log

Started GET "/test/index" for 127.0.0.1 at 2017-09-23 19:24:59 +0900
Processing by TestController#index as HTML
LOGGER TEST >>> debug
LOGGER TEST >>> info
LOGGER TEST >>> warn
LOGGER TEST >>> error
LOGGER TEST >>> fatal
  Rendering test/index.html.erb within layouts/application
  Rendered test/index.html.erb within layouts/application (1.0ms)
Completed 200 OK in 373ms (Views: 228.8ms)

pumaの標準出力

Started GET "/test/index" for 127.0.0.1 at 2017-09-23 19:24:59 +0900
Processing by TestController#index as HTML
LOGGER TEST >>> puts
LOGGER TEST >>> debug
LOGGER TEST >>> info
LOGGER TEST >>> warn
LOGGER TEST >>> error
LOGGER TEST >>> fatal
  Rendering test/index.html.erb within layouts/application
  Rendered test/index.html.erb within layouts/application (1.0ms)
Completed 200 OK in 373ms (Views: 228.8ms)

設定ファイル

config/environments/development.rb

Rails.application.configure do
  # Settings specified here will take precedence over those in config/application.rb.

  # In the development environment your application's code is reloaded on
  # every request. This slows down response time but is perfect for development
  # since you don't have to restart the web server when you make code changes.
  config.cache_classes = false

  # Do not eager load code on boot.
  config.eager_load = false

  # Show full error reports.
  config.consider_all_requests_local = true

  # Enable/disable caching. By default caching is disabled.
  if Rails.root.join('tmp/caching-dev.txt').exist?
    config.action_controller.perform_caching = true

    config.cache_store = :memory_store
    config.public_file_server.headers = {
      'Cache-Control' => "public, max-age=#{2.days.seconds.to_i}"
    }
  else
    config.action_controller.perform_caching = false

    config.cache_store = :null_store
  end

  # Don't care if the mailer can't send.
  config.action_mailer.raise_delivery_errors = false

  config.action_mailer.perform_caching = false

  # Print deprecation notices to the Rails logger.
  config.active_support.deprecation = :log

  # Raise an error on page load if there are pending migrations.
  config.active_record.migration_error = :page_load

  # Debug mode disables concatenation and preprocessing of assets.
  # This option may cause significant delays in view rendering with a large
  # number of complex assets.
  config.assets.debug = true

  # Suppress logger output for asset requests.
  config.assets.quiet = true

  # Raises error for missing translations
  # config.action_view.raise_on_missing_translations = true

  # Use an evented file watcher to asynchronously detect changes in source code,
  # routes, locales, etc. This feature depends on the listen gem.
  config.file_watcher = ActiveSupport::EventedFileUpdateChecker
end

test

コマンド	logファイル	pumaの標準出力
puts	×	○
logger.debug	○	×
logger.info	○	×
logger.warn	○	×
logger.error	○	×
logger.fatal	○	×

○：出力される / ×：出力されない

logファイル

log/test.log

Started GET "/test/index" for 127.0.0.1 at 2017-09-23 19:19:10 +0900
Processing by TestController#index as HTML
LOGGER TEST >>> debug
LOGGER TEST >>> info
LOGGER TEST >>> warn
LOGGER TEST >>> error
LOGGER TEST >>> fatal
  Rendering test/index.html.erb within layouts/application
  Rendered test/index.html.erb within layouts/application (1.2ms)
Completed 200 OK in 429ms (Views: 250.2ms)
Started GET "/assets/application-e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855.css" for 127.0.0.1 at 2017-09-23 19:19:10 +0900
Started GET "/assets/application-4e7bc2f1f25c80962b2c23f294cabed957b65d8e2e43ce258ea531eb0cd70bb1.js" for 127.0.0.1 at 2017-09-23 19:19:10 +0900

pumaの標準出力

LOGGER TEST >>> puts

設定ファイル

config/environments/test.rb

Rails.application.configure do
  # Settings specified here will take precedence over those in config/application.rb.

  # The test environment is used exclusively to run your application's
  # test suite. You never need to work with it otherwise. Remember that
  # your test database is "scratch space" for the test suite and is wiped
  # and recreated between test runs. Don't rely on the data there!
  config.cache_classes = true

  # Do not eager load code on boot. This avoids loading your whole application
  # just for the purpose of running a single test. If you are using a tool that
  # preloads Rails for running tests, you may have to set it to true.
  config.eager_load = false

  # Configure public file server for tests with Cache-Control for performance.
  config.public_file_server.enabled = true
  config.public_file_server.headers = {
    'Cache-Control' => "public, max-age=#{1.hour.seconds.to_i}"
  }

  # Show full error reports and disable caching.
  config.consider_all_requests_local       = true
  config.action_controller.perform_caching = false

  # Raise exceptions instead of rendering exception templates.
  config.action_dispatch.show_exceptions = false

  # Disable request forgery protection in test environment.
  config.action_controller.allow_forgery_protection = false
  config.action_mailer.perform_caching = false

  # Tell Action Mailer not to deliver emails to the real world.
  # The :test delivery method accumulates sent emails in the
  # ActionMailer::Base.deliveries array.
  config.action_mailer.delivery_method = :test

  # Print deprecation notices to the stderr.
  config.active_support.deprecation = :stderr

  # Raises error for missing translations
  # config.action_view.raise_on_missing_translations = true
end

事前準備

動作確認を行うために実施した準備と実行したコマンド

Controller

ページにアクセスしたい際にログ出力するControllerを作成する

$ rails g controller test index

class TestController < ApplicationController
  def index
    puts         'LOGGER TEST >>> puts'
    logger.debug 'LOGGER TEST >>> debug'
    logger.info  'LOGGER TEST >>> info'
    logger.warn  'LOGGER TEST >>> warn'
    logger.error 'LOGGER TEST >>> error'
    logger.fatal 'LOGGER TEST >>> fatal'
  end
end

サーバ起動＆ログ監視

ターミナル１：pumaの標準出力確認用
ターミナル２：logファイル確認用

production

ターミナル１

$ export SECRET_KEY_BASE=fd0d5cd5a488bee555851c83be8a19d37c253c07013894946e8037a50b03b1a223bfeb8e06a3c6e0f797447bd9cdecd6910906e8a42c3feb3cb52044393cd077
$ export RAILS_SERVE_STATIC_FILES=ON
$ rake assets:precompile RAILS_ENV=production
$ rails s -e production

ターミナル２

$ tail -f log/production.log 

development

ターミナル１

$ rails s -e development

ターミナル２

$ tail -f log/development.log 

test

ターミナル１

$ rails s -e test

ターミナル２

$ tail -f log/test.log 

ログ出力

ブラウザでページにアクセスしてログ出力させる
http://localhost:3000/test/index