« ^ »

JSONでフォーマットされた行指向のログを行指向ではない形に変換して出力する

所要時間: 約 4分

プログラムローカルで実行し動作を確認する時、そのプログラムの出力するログがJSONでフォーマットされた行指向のログを出力する事がある。ログの出力形式は設定で変更できる事が多いが、プログラム毎に異なる設定を毎度調べる事に疲れてしまった。賽の河原で石を積んでいる気分になる。まだ積み足りないのだろうか。もう疲れてしまった。だから、外側から出力されるJSONを整形するようにしようと思う。

そういった時に使えるのはjqコマンドだろう。jqコマンドは、標準入力からJSONを受け取り、そのデータを加工して標準出力に出力できる。連続してJSONが流れてくるようなデータもパイプを使用してjqに渡す事で1行ずつ解析と加工ができる。

例として取り上げるログは、JSONでフォーマットされた行指向のログであり、各行はmessage, level, timestampの3つの属性を常に持っている事とする。また3行目のmessageには改行文字が含まれている。

{"message": "test one!", "level": "info", "timestamp": "2023-03-17T03:14:52.224343Z"}
{"message": "test two!", "level": "warning", "timestamp": "2023-03-17T03:14:52.224343Z"}
{"message": "test three!\nok", "level": "error", "timestamp": "2023-03-17T03:14:52.224343Z"}
{"message": "test four!", "level": "critical", "timestamp": "2023-03-17T03:14:52.224343Z"}
使用するログの例

この形式は実際に存在するプログラムとしても、細かくは違うだろうけれど似た形式のログを出力しているのを見る。やり方の雰囲気さえ理解できれば、動作をカスタマイズする事は、それほど難しくない。jqの記法についてはjqの公式ドキュメントを見ると良い。

今回はこのログを出力するテスト用のスクリプトを記述する。出力は上記のログを1行ずつ1秒おきに標準出力に出力する。

echo '{"message": "test one!", "level": "info", "timestamp": "2023-03-17T03:14:52.224343Z"}'
sleep 1
echo '{"message": "test two!", "level": "warning", "timestamp": "2023-03-17T03:14:52.224343Z"}'
sleep 1
echo "{\"message\": \"test three!\\nok\", \"level\": \"error\", \"timestamp\": \"2023-03-17T03:14:52.224343Z\"}"
sleep 1
echo '{"message": "test four!", "level": "critical", "timestamp": "2023-03-17T03:14:52.224343Z"}'

outputlog.sh

では、このスクリプトの出力をjqにパイプで渡す。

bash outputlog.sh | jq
jqにパイプで渡す
{
  "message": "test one!",
  "level": "info",
  "timestamp": "2023-03-17T03:14:52.224343Z"
}
{
  "message": "test two!",
  "level": "warning",
  "timestamp": "2023-03-17T03:14:52.224343Z"
}
{
  "message": "test three!\nok",
  "level": "error",
  "timestamp": "2023-03-17T03:14:52.224343Z"
}
{
  "message": "test four!",
  "level": "critical",
  "timestamp": "2023-03-17T03:14:52.224343Z"
}

JSONが少し整形されている。

次にmessage属性のみ標準出力に出力する。

bash outputlog.sh | jq -r '.message'
jqにパイプで渡す
test one!
test two!
test three!
ok
test four!

-r がないとダブルクォートで括られた文字列として表示されてしまい、例えば改行文字がエスケープされた状態で出力される。それではJSONをそのまま出力しているのとあまり違いがない。改行はエスケープされず改行されて欲しい。そのため -r を指定し、出力を生の文字列(raw string)として扱うようにしている。

これでログのメッセージを出力できた。ただし、ログレベルも同時に確認したい。jqでは()を使うことで、同じレベルに位置する属性も扱うことができる。そこでlevel属性とmessage属性を両方出力するようにし、ついでにタブ文字で区切るようにする。

bash outputlog.sh | jq -r '(.level) + "\t" + (.message) '
info    test one!
warning test two!
error   test three!
ok
critical        test four!

() を使いlevel属性とmessage属性を両方取得し、 + を使い文字列結合している。ただし、なんだかlevelの文字列が8文字以上あるものがあり、少しだけ表示が崩れてしまう。ではlevelの文字列を半角空白で10文字分だけ左パディングする。

bash outputlog.sh | jq -r '(.level | (" " * (10 - length)) + .) + "\t" + (.message)'
      info      test one!
   warning      test two!
     error      test three!
ok
  critical      test four!

かなりログが見やすくなった。

毎回、この記述をコマンドの最後に付けるのは面倒なので、bashのエイリアスとして定義することにした。

alias prettylog="jq -r '(.level | (\" \" * (10 - length)) + .) + \"\t\" + (.message)'"
$ bash outputlog.sh | prettylog
      info      test one!
   warning      test two!
     error      test three!
ok
  critical      test four!

悪くはないけれど、もう少し複雑にしようとすると、エスケープシーケンスお化けが誕生して、1週間後には意味がわからない状態になってしまいそうな予感がする。エイリアスにはせず、スクリプトとして記述してしまう方が良さそうだ。execコマンドを使って、jqを呼び出すようにする。

#! /usr/bin/env bash
exec jq -r '(.level | (" " * (10 - length)) + .) + "\t" + (.message)'

prettylog

実行する。

$ bash outputlog.sh  | bash ./prettylog 
      info      test one!
   warning      test two!
     error      test three!
ok
  critical      test four!

このprettylogに実行権限を与え、パスの通った場所に置いておけばよさそうだ。しばらくはこれを使おうと思う。

https://github.com/TakesxiSximada/emacs.d/blob/main/bin/prettylog に置いておく。