Rustのログ出力，logクレートとenv_loggerクレートについて （Actix_webのログ出力も含む）
ナマステ！
neruneruna7です．
Actix-webを触っていて，Rustのログ出力について気になったので調べました．
一部actixを使用したサンプルコードが出てきます．
環境
Ubuntu 22.04.2 LTS WSL2
rustc 1.68.2
cargo 1.68.2
はじめに
（この章は，Actix_webを使っていない人は適当に流し読みして下さい）
さて，次のようなコードはActix-webにおいてよくあると思います．
logクレート，env_loggerクレート，Loggerミドルウェアを使った最小構成と言ってもいいでしょう．
use actix_web::{get, App, HttpServer, Responder};
use actix_web::middleware::Logger;
#[get("/index")]
async fn index() -> impl Responder {
"Hello World!"
}
#[actix_web::main]
async fn main() -> std::io::Result<()> {
env_logger::init_from_env(env_logger::Env::new().default_filter_or("info"));
log::info!("starting HTTP server at http://localhost:8080");
HttpServer::new(|| App::new().service(index))
.wrap(Logger::default())
.bind(("127.0.0.1", 8080))?
.run()
.await
}
このコードをコピペして cargo run しても動くはずです．
ところで，env_loggerを使っていますよね．何気なく使っているかもしれませんが，これは一体何でしょう？
init_from_env()でなにかゴニョゴニョしていますが，Loggerにどんな影響をもたらすのでしょう？
logとenv_loggerクレートとは？
log
最新版のドキュメントはこちら
logクレートとは，Rustでログ出力する際のメジャーなクレートです．
上記のコードにもある簡単な例を挙げると
~~~
log::info!("starting HTTP server at http://localhost:8080");
~~~
上記のように書くと，ログが出力されます．
logクレートのinfoマクロを使っていますね． 後述するinfoレベルでログを出力しています．
env_logger
最新版のドキュメントはこちら
env_loggerクレートは，logクレートを使ってログを出力する際に，出力するログのレベル指定を 環境変数ではなく グローバルロガーに設定することができます．
ここで言っている環境変数とはどの環境変数でしょうか？
それはRUST_LOGです．
RUST_LOGには，5つのレベルがあります．
グローバルロガーのログレベルには5つのレベルがあります．
- error
- warn
- info
- debug
- trace
ログレベルは、上記のように重要度の高いものから低いものまで順に並べられています。
つまり、ログレベルが高いものはログが出力される頻度が少なく、低いものは頻度が多くなります。
例えば、"error" は致命的なエラーが発生した場合に使用され、"trace" は詳細なデバッグ情報を出力するために使用されます。
"info" レベルのログは、プログラムの動作状況を把握するために役立ちます。
一般的には、アプリケーションが開始されたこと、リクエストが受信されたこと、ファイルが読み込まれたことなど、重要なイベントが発生した場合に使用されます。
通常、infoレベルのログは、デバッグやトラブルシューティングのために必要な最低限の情報を提供することが期待されます。
ChatGPTくんも言ってくれましたが， infoレベルを使うことが多いでしょう．
- どのように指定するのか?
~~~
env_logger::init_from_env(env_logger::Env::new().default_filter_or("info"));
~~~
init_from_env()はEnv型の引数をとります．
Env::new()でEnv型のインスタンスを作成し，default_filter_orでログレベルを指定しています．
今回は infoレベルを指定しています．
init_from_env()でログ出力を設定します．
あるいはRUST_LOG環境変数にログレベルを指定したうえで，init()を使うこともできます．
コード中で環境変数を設定する場合は，以下のようにします．
~~~
env::set_var("RUST_LOG", "info");
env_logger::init();
~~~
Actix_webのHttpServerの中で
~~~
.wrap(Logger::default())
~~~
の形でLoggerミドルウェアを使用して，設定したログレベルのログを出力しているわけですね．
なぜ，init_from_env()の設定がLoggerに反映されているのか？
グローバルロガーに設定されているから，と言ってしまえばそれだけです．
ですが，いろいろと挙動を確認したくありませんか？
もちろん，私も確認したくなりました．
RUST_LOG環境変数のLogクレートへの影響を確認してみる
まずはRUST_LOG環境変数がLogクレートにどのように影響するか確認してみます．
そこで，次のコードを書いてみましょう．
use env_logger;
use log::{debug, info};
fn main() {
env_logger::init();
debug!("main.rs debug");
info!("main.rs info");
println!("main.rs Hello, world!");
}
env_logger::init()でグローバルロガーの設定を初期化しています． とくにログレベルは指定していませんね．
次にdebug!マクロで出力しています． これはdebugレベルの出力をします．
次にinfo!マクロで出力しています． これはinfoレベルの出力をします．
最後にいつものprintln!です．説明は不要でしょう．
では，実行してましょう．
次のように表示されるはずです．
Finished dev [unoptimized + debuginfo] target(s) in 2.11s
Running `target/debug/rust-sand`
Hello, world!
おや，println!の内容しか表示されていませんね．
では，RUST_LOGを確認してみましょう．
次のコードは，RUST_LOG環境変数を取得して表示する処理を追加しました．
use env_logger;
use log::{debug, info};
use std::env;
fn main() {
env_logger::init();
let rust_log = env::var("RUST_LOG");
debug!("Executing main.rs debug");
info!("main.rs info");
println!("Hello, world!");
println!("RUST_LOG={:?}", rust_log);
}
実行してみましょう．
RUST_LOG=Err(NotPresent)
おっと，Errです．
これは，RUST_LOGには何も設定されていないことを示しています．
では，次は何か手動で設定して実行してみましょう．
手動で設定するのは簡単です．
RUST_LOG=debug cargo runとすれば，debugレベルに設定して実行することができます．
結果はどうでしょうか？
[2023-04-27T12:08:30Z DEBUG rust_sand] Executing main.rs debug
[2023-04-27T12:08:30Z INFO rust_sand] main.rs info
Hello, world!
RUST_LOG=debug
おおお！ おめでとうございます！！ debungレベルのログが出力されています！infoレベルはdebugレベルよりも上のレベルなので同時に出力されていますね．
RUST_LOG=info cargo runとすれば，debugレベルは出力されずに，infoレベルだけ出力されることを確認できるでしょう．
これで，RUST_LOG環境変数はenv_loggerで初期化されるグローバルロガーを通し，Logクレートに影響することがわかりました．
env_loggerのRUN_LOG環境変数への影響を確認してみる
逆に，env_loggerのRUST_LOG環境変数への影響を確認してみましょう．
RUST_LOG環境変数は書かずに,
env_logger::init_from_env(env_logger::Env::new().default_filter_or("info"));としてみます．
use env_logger;
use log::{debug, info};
use std::env;
fn main() {
env_logger::init_from_env(env_logger::Env::new().default_filter_or("info"));
debug!("debug");
info!("info");
println!("RUST_LOG={:?}", env::var("RUST_LOG"));
}
実行してみましょう．
[2023-04-27T12:08:30Z INFO rust_sand] info
RUST_LOG=Err(NotPresent)
infoレベルのログが出力されています．
しかし，RUST_LOG環境変数はErr(NotPresent)となっていて，何も設定されていません．
このことから，あくまでenv_loggerはグローバルロガーを初期化するだけで，RUST_LOG環境変数には影響を与えないことがわかりました．
loggerミドルウェアへの影響
env_logger::init_from_env(env_logger::Env::new().default_filter_or("info"))
と，RUST_LOGにinfoを設定してからのenv_logger::init()
が同じであることをサクッと確認しましょう．
下記の2つのコードは同じログ出力をします.
（Loggerは内部でlogを使用しているからです．）
use actix_web::{get, App, HttpServer, Responder};
#[get("/")]
async fn index() -> impl Responder {
"Hello World!"
}
#[actix_web::main]
async fn main() -> std::io::Result<()> {
env_logger::init_from_env(env_logger::Env::new().default_filter_or("info"));
HttpServer::new(|| {
App::new()
.service(index)
.wrap(actix_web::middleware::Logger::default())
})
.bind(("127.0.0.1", 8081))?
.run()
.await
}
use actix_web::{get, App, HttpServer, Responder};
use std::env;
#[get("/")]
async fn index() -> impl Responder {
"Hello World!"
}
#[actix_web::main]
async fn main() -> std::io::Result<()> {
env::set_var("RUST_LOG", "info");
env_logger::init();
HttpServer::new(|| {
App::new()
.service(index)
.wrap(actix_web::middleware::Logger::default())
})
.bind(("127.0.0.1", 8081))?
.run()
.await
}
まとめ
これまでのことから以下のことがわかりました．
-
env_logger::init()はRUST_LOG環境変数を参照している． -
env_logger::init_from_env(env_logger::Env::new().default_filter_or("info"))はRUST_LOG環境変数に影響を与えない． -
env_logger::init()はグローバルロガーを初期化しており，ログ出力に影響を与えるのはグローバルロガーである．
Discussion