— October 02, 2015

Shell Programing のすすめ

はじめに

最近は一人のプログラマーに求められる仕事の範囲が広がっています。決まった工程の中で決まった仕事だけやっていればOKということは少なくなっていると思います。

そうすると、その場限りの単発の作業が増えてきますが、「単発」と言っても、本当に一回限りなのかそれをこれから何度も行うことになるのか、なかなか見えないことも多いでしょう。

shell によるワンライナーやスクリプトを使えると、こういう作業をこなす上で、大きな武器になります。

ここでは、問題をワンライナーで解決して、最終的にそれをスクリプトとしてまとめた事例をひとつ紹介します。

問題と背景

当社は、Eコマースサイトを運営していますが、一つのプラットフォームで多くのサイトを運営しており、また、CMS、カート、バックヤードなどの多彩な機能をサポートしています。そのため、単一機能、単一目的のサイトと比較して、トラフィックの変動が多く、予想しずらいという特性があります。

私が、このサイトの運用に関わるようになって、最初に問題になったのが、突発的にアクセスが増えて、レスポンスが遅くなることでした。セールや新製品の発売などビジネス的な要因で来るアクセス増には、充分耐えるサーバになっているし、予め準備できるので問題ないのですが、そうでない理由のアクセス増がありました。

具体的には次のようなパターンです。

あるサイトの全ページを一括でダウンロードしようとしたユーザがいたが、そのダウンロードツールの不具合のため、存在しないURLへのアクセスを繰り返した
ダウンロードページの設定ミスによって、対象ファイルを自動ダウンロードするはずが、特定ページに繰り返しアクセスしてしまうようになっていた
連絡ミスから、ステージングサーバで行なうはずのペネトレーションテストを、プロダクションサーバで行なってしまった

これらは、どれも、原因がわかっていれば個別に対処するのは簡単です。

しかし、最初に問題が発生した時点では、わかっているのは、突発的にシステムの負荷が増えて重くなったということだけです。原因がわからない状態で、どのように調査して原因をつきとめるのかというのが、このエントリの対象とする問題です。

問題が定義されていれば、それぞれの問題に対して最適なツールがありますが、問題が見えてない段階で手探りの調査、対策を行なう時には、Shell を中心とした Unix の基本コマンドが、大きな武器になります。

ワンライナーでアクセスログを調査する

負荷増大時に、まずすることは、アクセスログを見ることです。

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

これで、リアルタイムのログを見ることができますが、凄い勢いで流れていきます。そこで、すぐに ctrl-C で中断して、内容を確認してみます。

そこで、次に、特定のフィールドを抜き出してみます。

$ tail -f /var/log/nginx/access.log | awk '{print $4}'

これで、空白区切りの4つめのフィールドが表示されます。当社で使用している形式では、ここがリモートアドレスになります。

これによって、いくつかのフィールドをリアルタイム表示していると、どうも、リモートアドレスが偏っているような気がします。それで、次のコマンドで確認しました。

$ tail -1000 /var/log/nginx/access.log | awk '{print $4}' | sort | uniq -c | sort -n
1 "xxx.121.247.xxx",
1 "xxx.236.105.xxx",
...
...
...
27 "xxx.232.218.xxx",
27 "xxx.219.178.xxx",
74 "xxx.29.251.xxx",

tail -1000 は、最後の1000行を出力します。

sort | uniq -c | sort -n は、これでひとかたまりのイディオムです。行単位で同じ値の出現回数をカウントできます。

上記のコマンドは、「access.log の最新1000件からアクセス元ごとの件数を表示する」という意味になります。

このようなコマンドをいくつか繰り返して、特定のリモートアドレスから多数のアクセスが来ていることがわかりました。そこで、次にこのクライアントがどのようなアクセスをしているのかを調べます。

tail -1000 /var/log/nginx/access.log | grep xxx.29.251.xxx |  awk '{print $8}' | sort | uniq -c | sort -n
2 aaa.com
3 bbb.com
20 ccc.com

tailの後に grep でそのアドレスを含む行だけを抜き出して、先程と似たような処理で、アクセス先のドメインを調べてみます。( $8 にドメインが入っている )

アクセス先のドメインがわかったこと所で、そのドメイン(サイト)の社内の担当者に連絡を取って、心あたりがないかを聞いたり、アクセス制限をかけてもいいか確認したりできます。

突発的なアクセス増というのは、何らかのかたよりはあるので、このような調査をしていくうちにパターンや原因がわかってきます。

JSON 形式のログの処理

ここまでは、アクセスログからのフィールドの抽出に awk を使っています。awkは、-F オプションで区切り文字を指定して、フィールド単位のさまざまな処理をできるので、これでたいていのログに同じような処理を行なうことができます。

実際には、当社のアクセスログは、後述する logentires.com で利用するために、JSONに似た形式で出力しています。そこで、これを jq コマンドで処理する方法を書いてみます。

当社のログ形式は、nginc.conf で次のように指定しています。

log_format le_json '"time": "$time_iso8601", '
  '"remote_addr": "$remote_addr", '
  '"remote_user": "$remote_user", '
  '"host": "$host", '
  '"body_bytes_sent": "$body_bytes_sent", '
  '"request_time": "$request_time", '
  '"status": "$status", '
  '"request": "$request", '
  '"request_method": "$request_method", '
  '"http_referrer": "$http_referer", '
  '"http_user_agent": "$http_user_agent"';

access_log /var/log/nginx/access.log le_json;

出力される行は次のようになります。

"time": "2015-09-27T06:44:33+00:00", "remote_addr": "XXX.159.186.XXX", "remote_user": "-", "host": "www.xxxxxx.com", "body_bytes_sent": "184", "
request_time": "0.002", "status": "301", "request": "GET / HTTP/1.1", "request_method": "GET", "http_referrer": "-", "http_user_
agent": "-"

これを jq で処理するために、sed コマンドによって、各行を {} で挟むようにします。

$ tail -1000 /var/log/nginx/access.log | sed -e 's/^/{/' -e 's/$/}/' | jq .
{
  "http_user_agent": "Mozilla/5.0 (Linux; U; Android 4.4.2; en-us; LGLS620 Build/KOT49I.LS620ZV3) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/30.0.1599.103 Mobile Safari/537.36",
  "http_referrer": "http://www.xxxxx.com/",
  "request_method": "GET",
  "time": "2015-09-27T06:44:59+00:00",
  "remote_addr": "xxx.87.66.xxx",
  "remote_user": "-",
  "host": "www.xxxxx.com",
  "body_bytes_sent": "4880",
  "request_time": "0.034",
  "status": "200",
  "request": "GET /cms-css/159/base.css HTTP/1.1"
}
...

こうなっていれば、次のように、jqコマンドによって必要なフィールドを抜き出すことができます。

$ tail -1000 /var/log/nginx/access.log | sed -e 's/^/{/' -e 's/$/}/' | jq  -r .remote_addr

下記のように、jq で条件に合うデータを抜き出すこともできます。

$ tail -1000 /var/log/nginx/access.log | sed -e 's/^/{/' -e 's/$/}/' | jq 'select(.remote_addr == "xxx.87.66.xxx")'

多機能コマンド(スクリプト) とパイプライン

このような処理は、Ruby や Python などのスクリプト言語を使ってもほぼ同じような手間で書くことができます。また、awk や jq などは多機能なツールで、それ単体でも似たようなことができます。

それと、ここまでに書いたパイプラインによって、基本的なコマンドを組み合わせる方法はどちらが優れているでしょうか。

これは、個人の好みや問題の性質にもよるので、一般的な答えはありませんが、パイプライン(シェルによるワンライナー)の利点をひとつあげると、「単一機能に特化したツールは、使いやすく覚えやすく、性能面でも有利」ということが言えます。

上記の例で言えば、ファイルの最後にある最新データを処理する時には、ファイルサイズが一定の大きさを超えたら tail -1000 が一番速いと思います。tail は、ファイルを終端から処理するので、行数指定をした場合にも、ファイルサイズによらず一定の時間で処理を行なうことができます。

一般的なスクリプト言語を使った場合には、普通は、ファイルを先頭から処理して、内部のメモリに必要なデータを蓄積していって、ファイルの最後まで来た時に、メモリ上の変数を処理するようなアルゴリズムになると思います。つまり、普通に書けば、ファイルサイズに比例した処理時間がかかってしまいます。

スクリプト言語でも、 tail と同じアルゴリズムを実装すれば、ファイルサイズに依存しない定数時間での処理ができますが、使い捨てのスクリプトでそこまでやるのは、時間の無駄です。

実際に、Webサイトのアクセスログはかなりの行数になるので、想定しているような緊急の状況で試行錯誤を繰り返す場合には、tail によって、ほぼコストをかけずに最新データを抽出できることには、非常に意味があります。

アクセスログには、問題のリクエストだけではなく、多数の正常なリクエストが混じっています。全体的に見ているとわからない問題を、tailやgrepで、対象データを絞りこんでから集計することで、素早く把握することができました。

Sensu の監視スクリプト

さて、私は、上記のように、予想外の突発的なアクセスに対して、ワンライナーで調査、対策することを何度かしてから、下記のようなスクリプトを書き、Sensu に組み込んで定期的に実行するようにしました。

#!/bin/bash

THRESHOLD=200
LOGFILE=/var/log/nginx/access.log
TAILOPT="-1000"

TOPACCESS=`tail $TAILOPT $LOGFILE| sed -e 's/^/{/' -e 's/$/}/' | jq -r '.remote_addr' | sort | uniq -c | sort -nr | head -1`

COUNT=`echo $TOPACCESS | sed -e 's/ .*$//'`
ADDR=`echo $TOPACCESS | sed -e 's/^.* //'`

if [[ $COUNT -gt $THRESHOLD ]]
then
  echo "Warning: max access is $COUNT from $ADDR"
  dig -x $ADDR |grep '^[0-9]'
  echo "Top 3 hosts accessed from it"
  tail $TAILOPT $LOGFILE | grep $ADDR | sed -e 's/^/{/' -e 's/$/}/' | jq -r '.host' | sort | uniq -c | sort -nr | head -3
  echo "Top 3 requests from it"
  tail $TAILOPT $LOGFILE | grep $ADDR | sed -e 's/^/{/' -e 's/$/}/' | jq -r '.request' | sort | uniq -c | sort -nr | head -3
  exit 1
else
  echo "OK: max access is $COUNT from $ADDR"
  exit 0
fi

Sensuのプラグインは、標準出力に情報を出力する普通のスクリプトで、exit 1で終了すれば Warning exit 2なら Error になります。

このスクリプトは、Sensuから定期的に自動実行するだけでなく、障害発生時にも手動で実行して調査に使用しています。

実行例

$ ./check_dos.sh
Warning: max access is 221 from xxx.29.251.xxx
xxx.251.29.xxx.in-addr.arpa. 3600 IN    PTR p1234-xxxxx.tokyo.ocn.ne.jp.
Top 3 hosts accessed from it
    170 www.xxxx.jp
     17 www.yyyy.jp
     15 xxx.degica.com
Top 3 requests from it
    181 GET /xxxx HTTP/1.1
      3 GET /cms-css/284/base.css HTTP/1.1
      2 GET /yyyy HTTP/1.1

ほぼ、ワンライナーで使った処理の組み合せですが、dig -xによって、アクセス元のアドレスの情報を追加しています。

特定のアドレスから一定量以上のアクセスがあると、Sensu の通知として、Slackに上記のような情報が流れます。

これによって、問題があるアクセスなのかどうか、ひとめでわかるようになっています。

ここで注目していただきたいのは、調査の段階で使用していたワンライナーが、ほぼそのままスクリプトの中で使われていることです。

実際に、このスクリプトは、コマンドラインのヒストリをコピペして修正して書きました。コマンドラインで使用した時点で、基本的な動作確認は終わっているので、それを利用することで、書く労力を大幅に減らせたと思います。

なお、調査対象を件数でなく「直近10分間」のように時間で指定することも考えましたが、時間で抽出しようとすると、アクセスログを全件処理することになって時間がかかるので、正確さより処理の負荷を低くすることを重視して、このままにしました。

まとめ

ここで言いたいのは、「アクセスログを分析することに Shell スクリプトやワンライナーが適している」ということではありません。

目的がハッキリしているなら、専用のツールを使った方がいいです。当社も今は、logentries.com というサービスを利用しています。ここは、SQLに似た分析用の言語があって、複数のサーバのログを集約した上で、簡単にログを分析することができます。上記のような分析もガイド付きの検索画面から簡単に行なうことができます。

しかし、これは有料のサービスで導入のための手間もあって、有形無形のコストがかかります。導入前には、必ず、果たしてこのサービスが本当に必要なのだろうか、ということを検討する段階があると思います。

そういうゴールが見えてないモヤモヤした段階において、Shell を中心にした道具箱に慣れ親しんでおくと、とても便利だというのが、私の言いたいことです。つまり、次のような流れです。

シェルや Unix の基本コマンドに慣れておく
問題が見えない段階では、端末からコマンドを直接叩いて調査する
問題が確定したら、それをスクリプトとして保存しておき、少しづつ自動化していく
問題が再発するごとに自動化のレベルを上げて、シェルスクリプトではない専用のツールに乗り換えていく

ここで使ったコマンドについて細かい解説は省きましたが、事例を見ればだいたい想像がつくし、基本的な機能はすぐにわかります。コマンドの詳細でなくて、sort | uniq -c | sort -nr のようなイディオムをいくつか覚えておくと、勉強する時間に対するコストパフォーマンスが非常に高いと思います。

awkやsedやjqなどは、非常に機能が豊富で完全にマスターしようとすると、ほぼひとつの言語を覚えるくらいの時間がかかりますが、パイプラインの中で使うには、むしろ、ごく基本的なパターンに絞りこんで使った方がいいと思います。その方が、使い回しがききます。

新しいデータを調査、分析する時でも、入口で「一行一データのテキストデータ」への変換さえしてしまえば、いつもの通りの方法で、処理することができます。逆に出口をCSVやJSONのような標準形式にして出力すれば、RDBやスプレッドシートなどの専用のツールに連動させることもできます。

このように「モヤモヤした問題をハッキリさせながら、段階的に専用のツールによる自動化を実現していく」という種類の仕事の重要性が高まっていると思うのです。それに対する備えとして、Shell と Unix の基本コマンドをひととおり覚えておくということが役にたつと思います。

一緒にユニークな決済サービスを作ってくれる Rails エンジニアを募集中です！

多国籍なメンバーと一緒に仕事をしてみませんか？詳細はこちらのリンクです:D

Degicaの採用情報