🚀 ニフティ’s Notion

2024-09-23

【サーバ運用入門2024 #3】ログ調査

ログの調査 ログの概要 ロギングの必要性 どういう時にログの調査をするの？ 調査方法 ハンズオン システムログを調査しよう webアプリケーションのログを調査しよう
🏁この章の目指すところ🏁
・ ログの役割、どこにログがあるのかをなんとなく理解する
・ ログを調査する方法をなんとなく理解する

ログの調査

ログの概要
ロギングの必要性

ロギングはシステム開発において重要な役割を果たし、以下の目的で使用されます。

運用面：

  • システムの動作状況確認・異常検知
    • システムログを監視し、正常な動作や障害の早期検知する
  • セキュリティ監視
    • 不正アクセスやセキュリティ侵害を検出する
  • パフォーマンスの監視と最適化
    • ログデータを分析することにより、システムのボトルネックを特定する
  • 監査
    • 法的な要件を満たすために監査ログを維持する場合もある

開発面：

  • トラブルシューティング
    • アプリケーションの問題やエラーの原因を特定し、バグを修正する
    • デバッグログやスタックトレースにより開発中の問題を特定する
  • 履歴とユーザー行動の分析
    • システムの操作と変更の履歴を記録して、問題発生時に変更の影響を特定する
    • 履歴からユーザー行動を分析して、改善や新規機能開発に利用する
どういう時にログの調査をするの？
  • エラーまたは例外が発生したとき
    • プログラムが予期しない動作をしたり、エラーをスローした場合、ログを調査することで問題の原因を特定しやすくなります
  • システムのパフォーマンスが低下したとき
    • ログにはシステムの動作に関する詳細な情報が含まれているため、パフォーマンスの問題を特定するのに役立ちます
  • セキュリティ違反が疑われるとき
    • 不正アクセスやデータ侵害の試みがあった場合、ログを調査することで攻撃の詳細や範囲を理解することができます
  • システムの動作を監視または分析するとき
    • ログはシステムの動作に関する貴重な情報を提供します。これを利用して、システムの使用状況を理解したり、将来の問題を予測したりすることができます

調査方法

ログの調査には様々なコマンド、方法がありますが、一般的によく使われるものをいくつか紹介します。

  1. cat : ファイルの内容を表示します。全てのログを一度に見ることができます。 
    cat /path/to/your/logfile.log
    サンプル 
    06:47:18 PM ❯ cat /path/to/your/logfile.log
2024-04-10 21:21:50,848:DEBUG:Data updated.
2024-04-11 02:04:14,362:INFO:User logged in.
2024-04-11 05:07:31,008:DEBUG:Server started.
2024-04-11 06:33:54,502:ERROR:User logged in.
2024-04-11 13:28:24,182:INFO:Error occurred.
2024-04-11 17:14:55,535:WARNING:Error occurred.
2024-04-11 18:14:11,176:DEBUG:Data updated.
2024-04-11 22:35:59,172:WARNING:Data updated.
2024-04-12 02:29:46,826:INFO:Data updated.
2024-04-12 16:45:25,465:DEBUG:Data updated.
2024-04-13 01:24:23,894:CRITICAL:Server started.
2024-04-13 07:23:47,616:WARNING:Server shut down.
2024-04-14 00:40:12,622:CRITICAL:Data updated.
2024-04-14 00:10:00,845:ERROR:User logged in.
2024-04-14 03:27:53,526:CRITICAL:Server shut down.
2024-04-14 06:29:58,826:ERROR:Error occurred.
2024-04-14 10:33:27,149:ERROR:Error occurred.
2024-04-14 10:21:07,091:DEBUG:Server shut down.
2024-04-14 12:14:40,898:ERROR:Server started.
2024-04-14 18:56:47,926:CRITICAL:Server started.
2024-04-14 20:00:19,939:DEBUG:Data updated.
(省略)
  2. less または more : ファイルの内容をページ単位で表示します。大きなログファイルを扱う際に便利です。
    1. 次ページへ f
    2. 前ページへ b
    3. 終了 q 
    less /path/to/your/logfile.log
    サンプル 
    2024-04-10 21:21:50,848:DEBUG:Data updated.
2024-04-11 02:04:14,362:INFO:User logged in.
2024-04-11 05:07:31,008:DEBUG:Server started.
2024-04-11 06:33:54,502:ERROR:User logged in.
2024-04-11 13:28:24,182:INFO:Error occurred.
2024-04-11 17:14:55,535:WARNING:Error occurred.
2024-04-11 18:14:11,176:DEBUG:Data updated.
2024-04-11 22:35:59,172:WARNING:Data updated.
2024-04-12 02:29:46,826:INFO:Data updated.
2024-04-12 16:45:25,465:DEBUG:Data updated.
2024-04-13 01:24:23,894:CRITICAL:Server started.
2024-04-13 07:23:47,616:WARNING:Server shut down.
2024-04-14 00:40:12,622:CRITICAL:Data updated.
2024-04-14 00:10:00,845:ERROR:User logged in.
2024-04-14 03:27:53,526:CRITICAL:Server shut down.
2024-04-14 06:29:58,826:ERROR:Error occurred.
2024-04-14 10:33:27,149:ERROR:Error occurred.
2024-04-14 10:21:07,091:DEBUG:Server shut down.
2024-04-14 12:14:40,898:ERROR:Server started.
2024-04-14 18:56:47,926:CRITICAL:Server started.
2024-04-14 20:00:19,939:DEBUG:Data updated.
2024-04-14 21:06:51,411:CRITICAL:Error occurred.
2024-04-14 23:40:30,107:CRITICAL:Error occurred.
2024-04-15 03:08:37,584:INFO:Server shut down.
2024-04-15 05:49:40,571:DEBUG:Data updated.
2024-04-15 07:24:21,474:ERROR:Error occurred.
2024-04-15 10:20:12,164:ERROR:Error occurred.
2024-04-15 11:16:33,088:ERROR:Error occurred.
2024-04-15 13:48:14,379:CRITICAL:Data updated.
2024-04-15 16:01:35,967:WARNING:Server started.
2024-04-15 19:07:29,784:WARNING:Server shut down.
2024-04-16 07:42:39,863:DEBUG:Error occurred.
2024-04-16 13:04:46,559:ERROR:Data updated.
2024-04-16 19:23:07,352:CRITICAL:Data updated.
2024-04-16 21:15:48,028:WARNING:Server started.
2024-04-16 22:17:52,562:CRITICAL:Server shut down.
2024-04-16 23:56:22,944:DEBUG:Data updated.
2024-04-17 00:14:32,004:INFO:User logged in.
2024-04-17 01:03:48,602:INFO:User logged in.
2024-04-17 07:10:57,395:WARNING:Server shut down.
2024-04-17 11:51:09,895:INFO:Server shut down.
2024-04-17 12:43:24,654:ERROR:Data updated.
2024-04-17 15:27:05,772:WARNING:Server shut down.
2024-04-17 23:54:46,696:CRITICAL:Data updated.
2024-04-18 00:20:22,123:DEBUG:User logged in.
2024-04-18 01:43:21,791:WARNING:Data updated.
2024-04-18 01:32:41,437:INFO:Server shut down.
2024-04-18 15:02:43,956:ERROR:Server started.
2024-04-18 18:39:13,442:WARNING:Data updated.
2024-04-19 00:15:56,513:DEBUG:Server started.
2024-04-19 04:34:00,047:INFO:Server shut down.
2024-04-19 12:47:07,388:INFO:User logged in.
2024-04-19 17:43:51,512:ERROR:User logged in.
2024-04-19 22:08:35,703:WARNING:Error occurred.
2024-04-19 23:47:54,149:INFO:Server started.
2024-04-20 03:51:22,082:INFO:Server started.
2024-04-20 09:34:00,985:CRITICAL:Error occurred.
2024-04-20 12:10:55,888:WARNING:User logged in.
2024-04-20 19:04:12,443:DEBUG:Server started.
:
  3. tail : ファイルの末尾部分を表示します。最新のログエントリを見るのに便利です。 f オプションを付けると、ログの更新をリアルタイムで追跡できます。 
    tail /path/to/your/logfile.log
tail -f /path/to/your/logfile.log
    サンプル 
    06:51:41 PM ❯ tail /path/to/your/logfile.log
2024-05-09 23:35:50,716:INFO:User logged in.
2024-05-10 01:51:31,144:INFO:Server started.
2024-05-10 03:54:00,543:CRITICAL:Server started.
2024-05-10 03:36:55,854:INFO:User logged in.
2024-05-10 04:46:01,922:DEBUG:Server shut down.
2024-05-10 04:40:37,198:CRITICAL:User logged in.
2024-05-10 05:46:55,919:INFO:Server started.
2024-05-10 09:21:26,962:CRITICAL:Server shut down.
2024-05-10 13:59:52,250:DEBUG:Error occurred.
2024-05-10 15:27:01,975:INFO:Error occurred.
  4. grep : ファイルから特定のパターンを含む行を検索します。エラーメッセージや特定のイベントを探すのに便利です。 
    grep "Error" /path/to/your/logfile.log
    サンプル 
    06:51:48 PM ❯ grep "Error" ./path/to/your/logfile.log
2024-04-11 13:28:24,182:INFO:Error occurred.
2024-04-11 17:14:55,535:WARNING:Error occurred.
2024-04-14 06:29:58,826:ERROR:Error occurred.
2024-04-14 10:33:27,149:ERROR:Error occurred.
2024-04-14 21:06:51,411:CRITICAL:Error occurred.
2024-04-14 23:40:30,107:CRITICAL:Error occurred.
2024-04-15 07:24:21,474:ERROR:Error occurred.
2024-04-15 10:20:12,164:ERROR:Error occurred.
2024-04-15 11:16:33,088:ERROR:Error occurred.
2024-04-16 07:42:39,863:DEBUG:Error occurred.
2024-04-19 22:08:35,703:WARNING:Error occurred.
2024-04-20 09:34:00,985:CRITICAL:Error occurred.
2024-04-21 18:26:42,907:DEBUG:Error occurred.
2024-04-22 14:42:17,898:DEBUG:Error occurred.
2024-04-23 06:15:02,705:INFO:Error occurred.
2024-04-24 16:06:27,650:INFO:Error occurred.
2024-04-24 20:02:17,373:INFO:Error occurred.
2024-04-25 22:50:56,753:CRITICAL:Error occurred.
2024-04-27 07:13:48,367:INFO:Error occurred.
2024-04-28 19:27:06,259:INFO:Error occurred.
2024-04-30 03:35:34,456:ERROR:Error occurred.
2024-05-01 20:09:32,305:CRITICAL:Error occurred.
2024-05-02 01:10:53,802:CRITICAL:Error occurred.
2024-05-02 13:07:20,425:DEBUG:Error occurred.
2024-05-02 15:10:56,526:INFO:Error occurred.
2024-05-02 16:33:33,092:INFO:Error occurred.
2024-05-03 14:37:21,560:CRITICAL:Error occurred.
2024-05-03 16:36:30,357:DEBUG:Error occurred.
2024-05-04 18:57:15,489:INFO:Error occurred.
2024-05-05 12:03:35,334:INFO:Error occurred.
2024-05-05 21:28:52,408:WARNING:Error occurred.
2024-05-08 00:03:29,525:DEBUG:Error occurred.
2024-05-09 19:50:31,399:WARNING:Error occurred.
2024-05-10 13:59:52,250:DEBUG:Error occurred.
2024-05-10 15:27:01,975:INFO:Error occurred.
  5. awk , sed : テキストの処理や変換を行います。ログの特定の部分を抽出したり、フォーマットを変更したりするのに使います。 
    awk '/Error/ {print $1, $2}' /path/to/your/logfile.log
sed 's/Error/ERROR/g' /path/to/your/logfile.log
    サンプル 
    06:53:08 PM ❯ awk '/Error/ {print $1, $2}' /path/to/your/logfile.log
2024-04-11 13:28:24,182:INFO:Error
2024-04-11 17:14:55,535:WARNING:Error
2024-04-14 06:29:58,826:ERROR:Error
2024-04-14 10:33:27,149:ERROR:Error
2024-04-14 21:06:51,411:CRITICAL:Error
2024-04-14 23:40:30,107:CRITICAL:Error
2024-04-15 07:24:21,474:ERROR:Error
2024-04-15 10:20:12,164:ERROR:Error
2024-04-15 11:16:33,088:ERROR:Error
2024-04-16 07:42:39,863:DEBUG:Error
2024-04-19 22:08:35,703:WARNING:Error
2024-04-20 09:34:00,985:CRITICAL:Error
2024-04-21 18:26:42,907:DEBUG:Error
2024-04-22 14:42:17,898:DEBUG:Error
2024-04-23 06:15:02,705:INFO:Error
2024-04-24 16:06:27,650:INFO:Error
2024-04-24 20:02:17,373:INFO:Error
2024-04-25 22:50:56,753:CRITICAL:Error
2024-04-27 07:13:48,367:INFO:Error
2024-04-28 19:27:06,259:INFO:Error
2024-04-30 03:35:34,456:ERROR:Error
2024-05-01 20:09:32,305:CRITICAL:Error
2024-05-02 01:10:53,802:CRITICAL:Error
2024-05-02 13:07:20,425:DEBUG:Error
2024-05-02 15:10:56,526:INFO:Error
2024-05-02 16:33:33,092:INFO:Error
2024-05-03 14:37:21,560:CRITICAL:Error
2024-05-03 16:36:30,357:DEBUG:Error
2024-05-04 18:57:15,489:INFO:Error
2024-05-05 12:03:35,334:INFO:Error
2024-05-05 21:28:52,408:WARNING:Error
2024-05-08 00:03:29,525:DEBUG:Error
2024-05-09 19:50:31,399:WARNING:Error
2024-05-10 13:59:52,250:DEBUG:Error
2024-05-10 15:27:01,975:INFO:Error

これらのコマンドはパイプ( | )を使って組み合わせることができ、より複雑な検索やフィルタリングを行うことができます。

例えば、 grep でエラーメッセージを検索し、 tail で最新のものだけを表示する、といったことが可能です。 

grep "Error" /path/to/your/logfile.log | tail
サンプル 
06:52:25 PM ❯ grep "Error" /path/to/your/logfile.log | tail
2024-05-02 16:33:33,092:INFO:Error occurred.
2024-05-03 14:37:21,560:CRITICAL:Error occurred.
2024-05-03 16:36:30,357:DEBUG:Error occurred.
2024-05-04 18:57:15,489:INFO:Error occurred.
2024-05-05 12:03:35,334:INFO:Error occurred.
2024-05-05 21:28:52,408:WARNING:Error occurred.
2024-05-08 00:03:29,525:DEBUG:Error occurred.
2024-05-09 19:50:31,399:WARNING:Error occurred.
2024-05-10 13:59:52,250:DEBUG:Error occurred.
2024-05-10 15:27:01,975:INFO:Error occurred.

これらのコマンドは基本的なもので、具体的な使用方法はログの内容や調査の目的によります。

また、これらのコマンドはローカルのシステムでログファイルに直接アクセスできる場合に使用します。

リモートのシステムやクラウドサービスのログを調査する場合は、そのサービスが提供するログ閲覧ツールやAPIを使用することが多いです。

ハンズオン

システムログを調査しよう

linuxのログの場所

  • 主なログファイルは/var/log配下 
自分のサーバーでの作業
# ルートユーザーになる
sudo su -
cd ..
cd /var/log
ls -l

Linuxの主なシステムログファイルの種類

  • /var/log/boot.log システム起動時のログ(システムの起動プロセス)
  • /var/log/maillog メールシステムのログ
  • /var/log/cron cronのログ
  • /var/log/secure 認証関連のログ
  • /var/log/dmesg システム起動時のdmesgの内容(カーネルからのメッセージ)
  • /var/log/lastlog 最終ログイン情報の記録
  • /var/log/wtmp ログイン情報の記録
  • /var/log/messages 上記に含まれないログ
  • /var/log/audit : システムの監査ログ(システムのセキュリティ関連のイベント)
  • /var/log/btmp : 失敗したログイン試行に関するログ
  • /var/log/journal : システムのログ
  • /var/log/tallylog : ログイン失敗の回数を記録するログ
  • /var/log/yum.log : パッケージマネージャーyumによるインストールやアップデートのログ

以降は共用のサーバで行います。

🚫 Post not found でやった通りに自分のサーバと共用サーバにログインしておいてください。

課題１　ログイン情報を調べてみる
  • 自分が共有サーバに初めてログイン日時はいつ？
ヒント 
# rootユーザーになっておく
$ sudo su -

# wtmpはバイナリ形式で保存されており、普通に開くと文字化けするのでlastコマンドで開く
$ last -f /var/log/wtmp
ec2-user pts/0        ip-192.0.2.0.ap- Tue May 14 09:11   still logged in
ec2-user pts/0        ip-192.0.2.0.ap- Tue May 14 08:42 - 09:11  (00:29)
ec2-user pts/0        ip-192.0.2.0.ap- Tue May 14 07:34 - 07:34  (00:00)
ec2-user pts/0        ip-192.0.2.0.ap- Tue May 14 07:17 - 07:18  (00:00)
ec2-user pts/0        ip-192.0.2.0.ap- Tue May 14 07:15 - 07:17  (00:02)
ec2-user pts/0        ip-192.0.2.0.ap- Tue May 14 07:10 - 07:14  (00:03)
ec2-user pts/0        192.0.2.2    Tue May 14 06:56 - 06:56  (00:00)

課題２　自分の認証ログを調べてみる
  • 自分のサーバのipアドレスで認証ログを眺めてみる
ヒント 
[root@hogehoge ~]# cat /var/log/secure | grep hogehoge <- 自分のサーバのipが当てはまるものを表示
May 14 06:23:33 hogehoge sshd[3169]: Connection closed by hogehoge port 39728 [preauth]
May 14 07:10:37 hogehoge sshd[3404]: Accepted publickey for ec2-user from hogehoge port 54002 ssh2: RSA SHA256:jkVw2axul0D1S1gJdv4jcy/KzGY5XKuvdKw2N6XPzLw
May 14 07:14:31 hogehoge sshd[3454]: Received disconnect from hogehoge port 54002:11: disconnected by user
May 14 07:14:31 hogehoge sshd[3454]: Disconnected from hogehoge port 54002
May 14 07:14:58 hogehoge sshd[3482]: Invalid user sci02173 from hogehoge port 38366
May 14 07:14:58 hogehoge sshd[3482]: Connection closed by hogehoge port 38366 [preauth]
May 14 07:15:13 hogehoge sshd[3484]: Accepted publickey for ec2-user from hogehoge port 44860 ssh2: RSA SHA256:jkVw2axul0D1S1gJdv4jcy/KzGY5XKuvdKw2N6XPzLw
May 14 07:17:27 hogehoge sshd[3534]: Received disconnect from hogehoge port 44860:11: disconnected by user
May 14 07:17:27 hogehoge sshd[3534]: Disconnected from hogehoge port 44860
May 14 07:17:41 hogehoge sshd[32337]: Connection closed by hogehoge port 41170 [preauth]
May 14 07:17:55 hogehoge sshd[32387]: Accepted publickey for ec2-user from hogehoge port 44038 ssh2: RSA SHA256:jkVw2axul0D1S1gJdv4jcy/KzGY5XKuvdKw2N6XPzLw
May 14 07:18:09 hogehoge sshd[32437]: Received disconnect from hogehoge port 44038:11: disconnected by user
May 14 07:18:09 hogehoge sshd[32437]: Disconnected from hogehoge port 44038
May 14 07:34:17 hogehoge sshd[32475]: Accepted publickey for ec2-user from hogehoge port 39898 ssh2: RSA SHA256:jkVw2axul0D1S1gJdv4jcy/KzGY5XKuvdKw2N6XPzLw
May 14 07:34:19 hogehoge sshd[32525]: Received disconnect from hogehoge port 39898:11: disconnected by user
May 14 07:34:19 hogehoge sshd[32525]: Disconnected from hogehoge port 39898
May 14 08:42:37 hogehoge sshd[311]: Accepted publickey for ec2-user from hogehoge port 48290 ssh2: RSA SHA256:jkVw2axul0D1S1gJdv4jcy/KzGY5XKuvdKw2N6XPzLw
May 14 09:11:45 hogehoge sshd[361]: Received disconnect from hogehoge port 48290:11: disconnected by user
May 14 09:11:45 hogehoge sshd[361]: Disconnected from hogehoge port 48290
May 14 09:11:47 hogehoge sshd[532]: Accepted publickey for ec2-user from hogehoge port 33022 ssh2: RSA SHA256:jkVw2axul0D1S1gJdv4jcy/KzGY5XKuvdKw2N6XPzLw

  • これまでに共有サーバにログインしたサーバのipアドレスは？
ヒント 
grep 'Accepted publickey' /var/log/secure | awk '{print $11}' | sort | uniq
  • 不正アクセスの疑いがあるものは？
    • 頻繁な認証失敗はありますか？
ヒント 
grep 'Invalid user\|Failed password' /var/log/secure | awk '{print $(NF-3)}' | sort | uniq -c | sort -nr

webアプリケーションのログを調査しよう

共用サーバは実はTODOアプリのAPIが動作しているサーバでもありました(という設定) 

# ログの場所
gin_sample/access.log
  • まずはログがどのようなフォーマットで出力されているのかをみてみよう！
    • 日時はどこに表示されている？
    • どういう内容？

課題１　6月3日のうち、最もリクエストが多かった時間帯は何時ですか？
ヒント① 
# 9時のアクセスを数えてみる
grep '2024/06/03 - 09:' access.log | wc -l
ヒント② 
# 各時間帯のアクセス数を数え上げる
grep '2024/06/03 -' access.log | cut -d' ' -f4 | cut -d':' -f1 | sort | uniq -c

# 流れ
grep '2024/06/03 -' access.log：ログファイルから2024年6月3日の行を抽出
cut -d'　' -f4：" "で区切られた５つ目の文字列を取得(日時)　ex.12:21:08
cut -d':' -f1：":"で区切られた1つ目の文字列を取得(何時か) ex.12
sort：時間をソート
uniq -c：重複する時間をカウント
課題２　どのエンドポイント(パス)が最も多くのリクエストを受けましたか？
ヒント 
# エンドポイントごとにアクセス数を数え上げる
grep '2024/06/03 -' access.log | cut -d'|' -f5 | sort | uniq -c | sort -nr

# 流れ
grep '2024/06/03 -' access.log：ログファイルから2024年6月3日の行を抽出
cut -d'|' -f5："|"で区切られた５つ目の文字列を取得(エンドポイント)
sort：エンドポイントをソート
uniq -c：重複するエンドポイントをカウント
sort -nr：リクエスト数で降順にソート

エンジニア定例 サーバ運用入門 2024