はじめに

こんにちは。テックリードのかどたみです。今回も、構造化ログネタです。弊社ではマイクロサービス開発を複数種類の言語、フレームワークで行っていますが、ある程度統一されたフォーマットのログを出力し、運用の円滑化を図っています。アプリケーションサーバーのログはほぼ対応し切っており、今までもいくつか方法を紹介しています。

今回紹介するOpenRestyはnginxにluaのモジュールなどをパッケージングしてアプリケーションサーバーやゲートウェイを構築できるOSSです。我々はゲートウェイとして利用しており、トラフィックもかなりの量ですが、ログの構造化に踏み出せておらず、トレースする際、ボトルネックになることもありました。

そこで重い腰を上げ、OpenRestyのログも構造化したのでその試行錯誤をご紹介します。

やりたかったこと

他のマイクロサービス同様以下のような内容をJSON形式で出力することを目標としていました。

ログレベルや出力時間、ステータスコードといった基本情報
フロントエンドからのリクエストで一意になるID
各マイクロサービスが受け取るリクエストで一意になるID(execution_id)
実行開始時刻

アクセスログはもちろんのことエラーログもJSON化し、トレースしやすいログを目指しました。しかし、結果として一部想定した通りのログにすることができませんでした。うまくいったこと、いかなかったことをまとめてみます。

うまくいったこと

アクセスログは簡単にJSON化することができました。ドキュメントにもあるようにフォーマットとその内容を記載するだけです。

   log_format nginxlog_json escape=json '{ "time": "$log_timestamp", '
        '"level": "$level", '
        '"message": "$log_message", '
        '"trace_id": "$trace_id", '
        ‘“original_content”: “$original_var”’
    ' }';
    access_log /dev/stdout nginxlog_json;

$で始まる変数はnginx側が用意してくれているものが多いですが、どうしてもそれだけでは実現したい内容にそぐわないことがあります。そのような場合は設定ファイルの中で変数を定義することができます。

server {
    …

    set $original_var “”;

    …
}

その後定義した変数を自由に書き換えることもできます。

ngx.var.original_var = “this is an updated value!”

OpenRestyは様々なdirectiveが提供されており、それらの内部でluaを用いたロジックを記述することができます。ログのマスキングなどでよく利用されていますね。今回はログの整形なので log_by_lua_block の内部で必要な変数を上書きしています。

server {
    …

    set $original_var “”;

    …
    log_by_lua_block {
        ngx.var.original_var = “this is an updated value!”
    }
}

これによってアクセスログを自由に書き換えることが可能になりました。

さらに、以下のようなloggerをluaで記述することにより、luaの処理の途中で好きな時に同様のログを出力することも可能になります。

local lib = {}

function lib.info(message)
    io.stderr:write(lib.create_log(message, "INFO"))
end

function lib.create_log(message, severity)  
    ngx.var.original_var = “this is an updated value!”
    local log = "{" ..
        "\"time\":\"" .. ngx.var.log_timestamp .. "\"," ..
        "\"severity\":\"" .. severity .. "\"," ..
        "\"message\":\"" .. message .. "\"," ..
        "\"trace_id\":\"" .. ngx.var.trace_id .. "\"," ..
        "\"original_content\":\"" .. ngx.var.original_var .. "\"," ..
    "}"

    return log
end

できなかったこと

さて、問題だったのはエラーログです。しかし、すべてのエラーログがうまくいかなかったわけではありません。luaが発生させるエラーに対してはJSONログを出力させることができました。luaで発生するエラーをcatchして500系エラーにし、nginxのエラーページを返すlocationでアクセスログと同様に log_by_lua_blockで必要な変数を上書きすれば期待する値を持ったログになります。

error_page 500 502 503 504 /50x.html;
location = /50x.html {
    …

    log_by_lua_block {
        ngx.var.original_var = “this is an updated value!”
    }

    …
}

では、どんなエラーログが構造化できなかったのか、それはnginx自体が出す以下のようなエラーログです。

2024/07/16 01:21:40 [error] 12#12: *13 connect() failed (111: Connection refused) while connecting to upstream, client: 172.25.0.1, server: localhost, request: "GET /hoge/huga/piyo HTTP/1.1", upstream: "http://127.0.0.1:5001/hoge/huga/piyo", host: "localhost:7001"

これらのエラーはluaでのログ整形もエラー自体のcatchもできないためそのまま出力されてしまいます。さらに、nginxはアクセスログのフォーマット指定はできますが、エラーログのフォーマット指定はできません。。。色々試行錯誤したのですが、どうしても構造化する事はできませんでした。なので、最低限このようなエラーが起こった際に、どのエンドポイントでどのようなステータスコードのエラーが起こったのかだけはlua側で判定し、JSONログを出しています。

{ "time": "2024-07-16T01:21:40Z", "severity": "ERROR", "message": "Bad Gateway. access url: GET /hoge/huga/piyo HTTP/1.1", "trace_id": "f433b66376688e1b3f3ba48aeb0efdb7", "original_content": "this is an updated value!" }

一部のエラーは構造化されませんが、最初の状態に比べればトレースはしやすくなったと思うので現状はこの形で運用することにしました。

今後どうする？

このままOpenRestyを使い続けるのであれば、ログパーサーをサイドカーとしてデプロイしてnginxが出すエラーを構造化した形に変換して出力するのが簡単かなと思っています。

それ以外にもOpenRestyをやめて新しく作り直すという選択肢もありますが、ログの構造化ができるかどうかを調べてから再実装する必要があり、骨が折れそうなのでまた別の機会に調査して技術選定できればと思います。もし、おすすめのゲートウェイ用のフレームワークがあれば教えて下さい。

おわりに

いかがでしたでしょうか？今回はOpenRestyのログ構造化についての試行錯誤について紹介しました。最低限の要件は満たせたものの完璧とは言い難い結果になりましたが、luaやnginxについて理解を深める良い機会になりました。マイクロサービス開発に興味がある方はぜひ採用ページからご応募お願いいたします。

hrmos.co