最初に

みなさん、こんにちは。エンジニアの Hodoshima です。 弊社では、Ruby で記述されたコードにおいて、データベースとのやりとりを行うために、ActiveRecord という gem を使っています。

ActiveRecord の機能として、データベースとのやりとりを行った際にリクエストした SQL を出力に渡すという機能があるのです。今回はこの機能をカスタマイズすることによって、快適にしてみましたので、ぜひみなさんも参考にしてみてください。

この記事に関する注意点

この記事ではデータベースを MySQL としています。

他のデータベースを使う場合、SQL や表示される内容に違いがある可能性がありますが、基本的にはどのデータベースでも同じような結果になります。

ActiveRecord のログ出力について

ActiveRecord では、ActiveRecord::Base.logger に出力先を指定することによって、ActiveRecord がデータベースに発行した SQL を、指定した出力先に出力する機能があります。

例えば、以下のようなテスト用のデータベースとテーブルを用意します。

CREATE DATABASE test;

CREATE TABLE test.users (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `name` char(64) DEFAULT NULL,
  `age` int(11) DEFAULT NULL,
  `message` longtext DEFAULT NULL,
  `created_at` DATETIME DEFAULT CURRENT_TIMESTAMP(),
  `updated_at` DATETIME DEFAULT CURRENT_TIMESTAMP() ON UPDATE CURRENT_TIMESTAMP(),
  PRIMARY KEY (`id`)
);

そして、今作ったテーブルに対して、ruby で以下のようなデータベースの基本的な 4 操作 (CRUD) を行うコードを書きました。

require 'active_record'

ActiveRecord::Base.establish_connection(
  adapter: 'mysql2',
  database: 'test',
  host: 'localhost',
  username: 'root',
  password: ''
)

ActiveRecord.default_timezone = :local
Time.zone_default = Time.find_zone! 'Tokyo'
ActiveRecord::Base.logger = Logger.new($stdout)

class User < ActiveRecord::Base; end

# Create
User.create(name: 'rooter', age: 26)

# Read
user = User.find_by(name: 'rooter')

# Update
user.update(age: 27)

# Delte
User.find_by(name: 'rooter').delete

このコードを実行すると、標準出力に次のような出力がされます。

この出力は ActiveRecord がデータベースとやりとりをした際に発行した SQL です。

SQL が標準出力に出力されたのは、コード内の

ActiveRecord::Base.logger = Logger.new($stdout)

という記述によって、ログを標準出力に吐き出すとしたためです。

このように ActiveRecord が吐き出すログを標準出力に吐き出すことによって、例えば、「コードが正しく動いているか?」や「データベースとのやりとりで滞留が発生していないか?」などといった点を確認することができ、保守の観点からでも有用な設計になっています。

また、行う操作によって色付けがされていたりするため、一目でどのような SQL を流したのかがわかりやすいです。

ログ出力の弱点

しかし、ActiveRecord にも弊社運用にフィットしない課題点がありました。 弊社では保守の観点からパース処理に失敗した JSON や HTML をログテーブルに格納して、障害発生の原因究明に利用することがあります。

ここで、ActiveRecord におけるデフォルトでのログ吐き出しは、SQL の全てを標準出力する設計になっています。

そのため、JSON や HTML といった 長い文字列のデータをテーブルに保存するしようとすると、発行された巨大なinsert文もログとして吐き出されてしまい、標準出力の画面を埋めてしまいます。

こうなってしまうと、保守のために吐き出したログのせいで保守がしにくくなってしまうという本末転倒な展開になってしまいます。

下のスクショでは、

User.create(name: 'rooter', message: 'X' * 20000)

を末尾に追加して実行しました。

ログ出力のカスタマイズ

ここで、ログ吐き出しのカスタマイズをしてみます。

カスタマイズの戦略や方法は何通りも考えられますが、今回は実際に SQL が流れているところさえ確認できれば具体的な中身の詳細は問わない信念により、「出力される SQL が長い場合に省略する」という方針でカスタマイズします。

以下のコードを書くと、出力される SQL が長い場合に省略することを実現してくれます。

class ActiveRecord::Base
  logger.formatter = proc do |severity, datetime, progname, log_message|
    if log_message.is_a?(String) and log_message.length >= 600
      # "\e[0m" → 出力される文字の装飾 (色や太文字など) をリセットする
      log_message = log_message.truncate(500) + "\e[0m"
    end
    "#{severity} [#{datetime}] #{log_message}\n"
  end
end

この記述を追加することで、長い SQL が発行されたとしても、途中から ... と表示されコンソール画面を占有しなくなります。

このコードの補足説明

• 500 や 600 といった数に対する論理的根拠はありません。使っている環境ごとに適切な数に変更にしてください。
• このコードでは 600 文字以上の時に 500 文字で打ち切る実装になっています。このように判定する長さと打ち切る長さの間に若干のバッファがないと、後述するように見た目が悪くなったり別のバグの原因になり得ます。
• log_message = log_message.truncate(500) + "\e[0m" と 500 文字に打ち切った後に、\e[0m という文字列を追加しています。この文字列は標準出力される文字の装飾をリセットする特殊な文字列です。これを描かないと、次のログ出力の頭に前の装飾が引き継がれてしまい、見た目が悪くなってしまいます。