Skip to content

8.7 - 当社サーバーのトラフィックを記録する

当社サーバーのトラフィックを記録する

今のところ、私たちのアプリケーションは何もログを記録していません。これはアプリの実行に直接影響するものではありません。しかし、ログを記録することにはいくつかの利点があります。ログを記録することで、アプリケーションのデバッグが可能になります。

今はローカルで開発しているため、ロギングはあまり必要ないように思えるかもしれません。しかし、本番環境では、Dockerコンテナのオーケストレーションの問題など、アプリケーションに障害が発生する理由はたくさんあります。どのような処理が行われたかを記録したログは、エラーを特定するのに役立ちます。また、エッジケースやエラーの発生をログで確認することで、アプリケーションの全般的な健全性を監視することができます。ロギングに関しては、構築可能なログの種類は4つあります。

インフォメーショナル（info）。これは一般的なロギングです。一般的なプロセスやその進行状況を追跡したい場合、このタイプのログを使用します。使用例としては、サーバーの起動と停止、HTTPリクエストなど監視したい特定のチェックポイントのログを記録します。 Verboseです。これは、前のポイントで定義したタイプのような情報です。ただし、より詳細なプロセスの流れを知らせるために、より細かくなっています。このタイプのログは、主にデバッグ目的で使用され、本番環境では一般的に避けるべきです。 警告このタイプは、失敗しているプロセスをログに記録する場合に使用されます。しかし、サービスを中断させたり、ユーザーに特定のエラーを知らせたりする必要がないため、エラーを発生させる代わりにこのタイプを使用することができます。ログは、問題が発生したことを知らせてくれるものであり、その後に対処できるようにするためのものです。他のサーバーへの呼び出しに失敗したなどの問題は、このカテゴリーに適しています。 エラー。エラーによってプロセスが中断され、できるだけ早く解決する必要がある場合です。また、トランザクションがうまくいかなかったことをユーザーに知らせる必要があります。この良い例は、データベースへの接続やデータの挿入に失敗した場合です。このような場合、トランザクションが起こったという記録はなく、過去にさかのぼって解決することはできない。しかし、プロセスの実行は継続できることに留意する必要があります。 サーバーが電子メールの送信に失敗したという警告が出た場合、別のサーバーに接続して商品を発送する、といった具合に。問題を整理すれば、この時間帯のトランザクションに対して、過去にさかのぼってデータベースの呼び出しを行い、正しい情報でサーバーに呼び出しを行うことができます。

最悪の場合、遅延が発生します。このエラータイプでは、注文がデータベースに入力される前にサーバーがエラーによって中断されたため、データベースコールを行うことができません。このように考えると、エラーログが非常に重要であることは明らかです。なぜなら、ユーザーには問題があり、トランザクションがうまくいかなかったことを伝え、後で再試行するように促す必要があるからです。

エラーログに十分な情報を含めることで、過去にさかのぼってデータベースを更新し、問題が解決した時点で残りのプロセスを完了させ、ユーザーに知らせる必要性をなくすという選択肢も考えられます。これは魅力的なことですが、2つのことを考慮する必要があります。ログデータは一般的に非構造化である。

ログに記録されるデータの品質管理はできません。そのため、最終的にログデータを正しいフォーマットに操作できたとしても、破損したデータがデータベースに入り込む可能性があります。

2つ目の問題は、ログが安全であると考えられていないことです。危機的な状況でコピーされて他の開発者に送られたり、ログを監視するために他のパイプラインやBugsnagなどのWebサイトに突っ込まれたりします。ログの性質を考えると、ログの中に個人を特定できるような情報があるのは良い習慣とは言えません。

ロギングの用途を理解したところで、独自のロガーを設定することができるようになりました。ロギングに関しては、Actix-webロガーを使用する予定です。これにより、ログの基本的な仕組みが構成され、Actixサーバーでうまく機能する一方で、ログの内容については柔軟に対応できます。ロガーを構築するには、Cargo.tomlファイルに次のコードで新しいクレートを定義する必要があります。

[dependencies]
. . .
env_logger = "0.9.0"

これにより、環境変数を使用してロガーを設定することができます。ロガーが設定され使用されるのは main.rs です。まず、次のコードでロガーをインポートします。

use actix_web::{. . ., middleware::Logger};

このインポートにより、以下のコードでmain関数内にロガーを定義することができます。

. . .
#[actix_web::main]
async fn main() -> std::io::Result<()> {
    . . .
    env_logger::init_from_env(env_logger::Env::new()
                              .default_filter_or("info"));
. . .

ここでは、ロガーが情報を情報ストリームに記録することを明記しています。ロガーが設定されたので、次のコードでサーバーをロガーでラップすることができます。

. . .
        async move {
            let result = end_result.await?;
            Ok(result)
        }
}).configure(views::views_factory).wrap(cors)
    .wrap(Logger::new("%a %{User-Agent}i %r %s %D"));
return app
. . .

ロガーでは、"&a %{User-Agent}I %r %s %D "文字列を渡したことが確認できます。この文字列はロガーによって解釈され、何をログに記録するかを指示します。Actixロガーは、以下の入力を受け取ることができます。

  • %%:パーセント記号
  • %a:リモートIPアドレス（リバースプロキシ使用時はプロキシのIPアドレス）。
  • %t:リクエストの処理が開始された時刻
  • P: リクエストを処理した子のプロセスID
  • %r:リクエストの最初の行
  • %s:レスポンスのステータスコード
  • %b:HTTP ヘッダーを含むレスポンスのサイズ（バイト）。
  • T：リクエストの処理に要した時間。秒単位で、浮動小数点は .06f の形式。
  • D：リクエストの処理に要した時間（単位：ミリ秒
  • %{FOO}i: request.headers['FOO'].
  • %{FOO}o: response.headers['FOO'].
  • %{FOO}e: os.environ['FOO'].

これらの入力により、リモートIPアドレス、ユーザーエージェント、リクエストのエンドポイント、リクエストの処理にかかった時間を記録することができます。これは、Rustサーバーが持つすべてのリクエストに対して行います。Rustサーバを起動してロギングを行うと、次のような出力が得られます。

[2022-05-25T17:22:32Z INFO  actix_server::builder] Starting 8 workers
[2022-05-25T17:22:32Z INFO  actix_server::server] Actix runtime found; starting in Actix runtime

ここでは、サーバーの起動時刻とワーカーの数が自動的に記録されていることがわかります。そして、フロントエンドを起動すると、トークンの有効期限が切れているはずなので、ログインするように促されるはずです。完全な標準リクエストログは、次のような出力になるはずです。

[2022-05-25T17:14:56Z INFO  actix_web::middleware::logger]
127.0.0.1 Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7)
AppleWebKit/537.36 (KHTML, like Gecko)
Chrome/101.0.4951.64 Safari/537.36
GET /v1/item/get HTTP/1.1 401 9.466000

時間、INFOレベルのログであること、そしてどのロガーがログを記録しているかがわかります。また、私のIPアドレス（アプリケーションをローカルで実行しているためローカル）、コンピュータやブラウザの詳細、レスポンスコード401のAPIコールも見ることができます。リクエストログからメソッド、APIエンドポイント、レスポンスコード、レスポンスタイムを除いてすべてを削除すると、ログインプロンプトは次のようになります。

GET /v1/item/get HTTP/1.1 401 9.466000
OPTIONS /v1/auth/login HTTP/1.1 200 0.254000
POST /v1/auth/login HTTP/1.1 200 1405.585000
OPTIONS /v1/item/get HTTP/1.1 200 0.082000
GET /v1/item/get HTTP/1.1 200 15.470000

アイテムの取得に失敗し、unauthorizedレスポンスが返ってきていることがわかります。次にログインしてみると、ログインからOKレスポンスが返ってきます。ここで、OPTIONSメソッドとPOSTメソッドを確認することができます。OPTIONSメソッドはCORSのためで、OPTIONSコールの処理時間は他のAPIリクエストの数分の一です。その後、アイテムが取得され、ページにレンダリングされることがわかります。しかし、ページを更新すると、次のようなログが表示されることがあります。

OPTIONS /v1/item/get HTTP/1.1 200 0.251000
OPTIONS /v1/item/get HTTP/1.1 200 0.367000
GET /v1/item/get HTTP/1.1 200 88.317000
GET /v1/item/get HTTP/1.1 200 9.523000

項目に対するGETリクエストが2つあることがわかります。しかし、データベース内のToDo項目は変更していません。これはエラーではありませんが、無駄が多いのです。これを最適化するために、次のセクションでキャッシュというRESTの制約を利用することができます。