読者です 読者をやめる 読者になる 読者になる

kzk-casino.com

一人前のITエンジニアを目指して

Webサーバのアクセスログ監視で使えるテクニック

Tech Tips

Webサーバのアクセスログは、障害時に情報を得る重要なヒントとなります。

ここでは、Nginxで稼働しているWebサーバに対して、アクセスログを監視するテクニックについて記載します。

環境準備

Webサーバ

まず、Webサーバを用意します。

今回はAWS上にAmazon Linuxで立てたインスタンスにnginxをインストールすることで簡易Webサーバを構築しました。

また、Grobal IPを割り当てて、インターネットからアクセスできるようにしました。

アクセスノード

アクセスログの監視なので、複数のIPからたくさんのWebアクセスをさせる必要があります。

そのためのアクセスノードとしてGCEのインスタンスを3つ立ち上げ、それぞれに下のようなスクリプトを配置しました。

スクリプト名:curl.sh

#!/bin/bash

while :
  do
    curl <WebサーバのGIP>
    sleep <N>s
  done
$ chmod 755 curl.sh

ここで、にはAWSに構築したNginxサーバのGlobal IPを記載し、には1~9くらいで適当な数字を入れます。
3つのインスタンスに異なるNを設定することで、各インスタンスからのアクセス数を変更させることができます。

適当に時間がたったらNの値を変えてみたりしてもいいと思います。

ログの出力

まず、Webサーバで下記のコマンドを実行して、アクセスログのリアルタイムモニタリングを実施します。

$ sudo tail -f /var/log/nginx/access.log

次にアクセスノード×3に配置したスクリプトを実行します。また、自分もブラウザからWebサーバにアクセスしてもいいかもしれません。

./curl.sh

すると、Webサーバに大量のアクセスログが出力されます。
f:id:kzk_casino:20161106140412p:plain

ログの確認

この大量のアクセスログをそのまま眺めていても、何もわかりません。

アクセスログを見るときに知りたい情報として、

  • どこからアクセスが来ているのか
  • いつ大量のアクセスが来たのか

といったものが挙げられると思いますが、これらを簡単に可視化する方法を記載します。

どこからアクセスが来ているのか

アクセスログの1行を抜き取ってみます。

130.211.126.93 - - [05/Nov/2016:14:48:51 +0000] "GET / HTTP/1.1" 200 3770 "-" "curl/7.38.0" "-"

デフォルトフォーマットでは、第一要素目にFromのIPが記載されています。
これを抜き取って集計しましょう。

先に答えを言うと、下記の様なコマンドで集計して可視化することができます。

$ sudo tail -10000 /var/log/nginx/access.log | grep "05/Nov/2016:14" | awk '{print $1}' | sort -n | uniq -c | sort

順番に意味を見ていきましょう。

  • sudo tail -10000 /var/log/nginx/access.log

access.logの末尾から10000行を表示します。
ログが大量にあるときは、サーバの負荷を下げるために出力量を抑えたほうがいいでしょう。

  • grep "05/Nov/2016:14"

ログから、2016/11/5の14:00台のものだけを抜き取っています。
障害が発生した時間が大方特定できるときはこの様にして出力量を絞っておきましょう。

  • awk '{print $1}'

ログの第一要素目、つまりFrom IPを抜き取っています。

  • sort -n

sortコマンドは、出力をソートする(並び替える)コマンドです。
"-n"オプションによって、数字を数字として認識してソートしてくれます。

  • uniq -c

uniqコマンドは重複行を排除して1行にまとめてくれるコマンドです。
"-c" オプションによって、重複した行数を出力してくれます。

  • sort

sortコマンドの再登場です。uniq -cで出力されたIPを少ない順に並び替えます。


このようにOSコマンドのChainでどのIPから大量にアクセスが来ているのかを計測することができます。

計測結果は下記のようになります。

$ sudo tail -10000 /var/log/nginx/access.log | grep "05/Nov/2016:14" | awk '{print $1}' | sort -n | uniq -c | sort
     23 60.68.26.60
    327 104.154.229.150
    400 130.211.126.93
    441 104.197.31.33

104.197.31.33からのアクセスが最も多いことがわかります。

いつ大量のアクセスが来たのか

もう一つ、アクセスログを用いて確認したい項目として、実際いつ大量のアクセスが来たのか、ということがあると思います。

またアクセスログの1行を抜き取って考えてみます。

130.211.126.93 - - [05/Nov/2016:14:48:51 +0000] "GET / HTTP/1.1" 200 3770 "-" "curl/7.38.0" "-"

上記ログを、区切り文字を":"として要素に分けると、

  • 第1要素:130.211.126.93 - - [05/Nov/2016
  • 第2要素:14
  • 第3要素:48
  • 第4要素:51 +0000] "GET / HTTP/1.1" 200 3770 "-" "curl/7.38.0" "-"

のように分解することができます。

第2要素と第3要素を用いて計測すれば、分単位でいつアクセスが集中したのかを可視化することができます。

これも先に答えをいうと、下記のコマンドで実行することができます。

$ sudo tail -10000 /var/log/nginx/access.log | grep "05/Nov/2016:14" | cut -d ":" -f 2,3 | sort | uniq -c

途中までは先に説明したものと同じなので、違いだけ解説します。

  • cut -d ":" -f 2,3

まさに、先に述べた「区切り文字を":"として要素に分けて、第2要素と第3要素を抜き取る」という行為をしています。
cutは文字列を分割してくれるコマンドで、"-d" でディリミタ(区切り文字)を指定し、"-f" で抜き取る要素番号を指定します。

  • sort

抜き取った出力を並び替えます。

  • uniq -c

前述の例同様、重複行を排除して重複行数をカウントしています。

こちらの計測結果は下記のようになります。

$ sudo tail -10000 /var/log/nginx/access.log | grep "05/Nov/2016:14" | cut -d ":" -f 2,3 | sort | uniq -c
      5 14:37
      9 14:38
      8 14:40
      3 14:41
     11 14:42
     53 14:43
     45 14:44
    214 14:45
    376 14:46
    374 14:47
     76 14:48
     17 14:49

14:46前後にアクセス量が多くなっていることがわかります。

まとめ

このようにOSコマンドを組み合わせて使用することで、「いつ」、「どこから」大量のアクセスが来たのかを確認することができます。
これはDoS攻撃の解析などにも使用することができます。

参考

uniq -c した結果をバーで可視化してくれるツールもあります。

Visualizing `uniq -c` result · GitHub

上記のコードをWebサーバにクローンして使用すると、下記のようにバーで計測結果を可視化してくれます。

f:id:kzk_casino:20161106142528p:plain

f:id:kzk_casino:20161106142533p:plain