1 2016/09/06 日本経済新聞社 梅崎 裕利 Elastic{ON} Seminar Tokyo 日経電子版のアプリ開発を 支えるログ活用術

2 About me • 梅崎 裕利（うめざき ゆうり） • 日本経済新聞社 2014年入社 • DevOps担当 ‒ Django+Elasticsearchで検索API・オートコンプリートAPIなど ‒ Fluentd+Elasticsearch+Kibanaでログ分析 ‒ Docker(Amazon Elastic Beanstalk)を使ったマイクロサービス化 ‒ Ansibleでサーバ管理

3 日本経済新聞 電子版でのElasticsearch利用 • 検索 ‒ 記事検索: 約500万記事、秒100クエリ前後 ‒ 企業名検索: 約5万件 • ログ分析 ‒ アクセスログ: 約3億件/日 × 7日 (ロードバランサのログ) + 約1000万/日 × 3 × 60日 (各バックエンドサービスのログ) + 約2億/日 × 7日(Cloudfront) ‒ ユーザ行動ログ: 約1000万件/日 × 数年 ‒ エラーログ

4 検索機能としてのElasticsearch利用箇所 • 検索画面 ‒ 記事検索 ‒ キーワードハイライト ‒ アグリゲーション ‒ オートコンプリート • 記事画面 ‒ 類似記事 • アプリ ‒ 紙面を撮って関連記事を表示

5 きょう主に話すこと • 検索 ‒ 記事検索: 約500万記事、秒100クエリ前後 ‒ 企業名検索: 約5万件 • ログ分析 ‒ アクセスログ: 約3億件/日 × 7日 (ロードバランサのログ) + 約1000万/日 × 3 × 60日 (各バックエンドサービスのログ) + 約2億/日 × 7日(Cloudfront) ‒ ユーザ行動ログ: 約1000万件/日 × 数年 ‒ エラーログ

6 ログ分析

7 アジェンダ • アクセスログとは • 分析にESを使うと何が嬉しいか • 具体的な利用例 ‒ ユーザ分析 ‒ 運用・障害対応 ‒ サービス改善 • 今後 ‒ 実験中のこと ‒ 課題 ‒ ES5.0に期待していること

8 アクセスログとは • Webサーバへのリクエストの詳細を記載したログ • アクセス日時・アクセス元IP・URL・処理時間・ステータスなど • サーバへの1リクエストにつき1行生成 • サーバの状況やユーザの行動を把握する上で重要

9 アクセスログを使った分析 • 従来 ‒ とりあえず圧縮して保管しておき、困ったときに秘伝のシェル芸を使って見る ‒ エラー数やアクセス数など、項目を事前に決めた上でバッチ集計して確認 • 問題点 ‒ バッチ集計結果から詳細が気になったときは分析が面倒 ‒ 確認方法が変わってしまうため、時間がかかる上に可視化しにくい ‒ 項目を増やすのが難しい（≒バッチがどんどん増える） ‒ ○○APIの平均レスポンス時間と人気なURLと毎時リクエスト数推移と… • 理想 ‒ データベースに全部突っ込んでおいて、あとで必要なメトリクスを集計する

10 分析にES+Kibanaを使うと何が嬉しいか • 目的に合わせて都度、条件を指定して集計できる ‒ 複数の条件を指定してメトリクスを確認 ‒ 抽象的な情報を見てより詳細に確認できる ‒ 目的の数値を変更 ‒ 例: レスポンス時間の平均値、最大値、99%タイル • 直接ログの中身が確認できる ‒ 詳細な分析がすぐに可能 • 高速 従来の問題が一通り解決

11 日経でのアクセスログ活用

12 普段は何を見ているのか • リクエスト数が急激に増えていないか • エラーが出ていないか • レスポンスが遅くなっていないか • 怪しげなリクエストが来ていないか • どのURLにリクエストが多いか • アクセスログ以外と組み合わせて ‒ データ転送量 ‒ CPU,メモリ使用量

13 Nginxのログフォーマット例

14 ダッシュボード • アクセス数、3秒以上かかったレスポンス数、攻撃検知、ステータス

15 Elastic契約でできること • しきい値を超えたらアラートを出す ‒ watcher • Kibanaに認証つけたり、権限管理できるようにする ‒ Shield

16 改善活動1 1. path毎の応答時間99%tile 2. 時系列順で何時頃遅いのか確認 3. 応答時間をX軸にして確認 4. 負荷・キャッシュ・エラーとの関連を見る 処理が遅いAPIを探す

17 改善活動2 • どのファイルが帯域を多く使ってるか ‒ レスポンスサイズの合計をパスごとに表示 • キャッシュヒット率を増やす ‒ etagをつける ‒ キャッシュ時間を長くする • gzipを有効にする ‒ gzip漏れはないか 帯域使用量を減らす

18 改善活動2 • どれぐらい減ったかすぐわかる Gzipを有効にしたとき

19 改善活動3 • デプロイ時に実は止まってたり、遅くなっていたりしないか ‒ 切り替え方によっては瞬断が発生しているのを可視化

20 ビジネス用途 • 現在のアクセス数をリアルタイム表示 ‒ ユーザ権限別 ‒ 記事別 ‒ 流入元調査 • クローラ数調査 (JSや画像ビーコンだと難しい)

21 実際にあった具体例

22 アプリ開発サポート • リクエストが異常に多いユーザがいる ‒ エラー時に無限リトライになっていた ‒ 非同期通信にバグがあった • 同じ画像に一人あたり数回リクエストしている ‒ 何度かリクエストする作りになっていた → 改修して通信量削減 • ログインできないという報告がある ‒ ログインでリトライしており不正アクセス検知に引っかかっていた • 権限エラーが出ている ‒ Client_IPやUA, ユーザID(独自ログ)などで対象の通信のみにフィルタ ‒ どこでエラーになっているか調査 ‒ 解約済みだった、期限切れトークンでリクエストしていたなど アプリのバグ調査

23 都度発生する特殊な障害対応/実際にあった例 • 調査：対象ブラウザ/影響ユーザ数を調べる 1. 該当pathリクエストのUAと、全体のUA一覧を取得 2. 全体のUA一覧から該当pathのUA一覧を除いたリストを作成 • 原因 ‒ SSLの設定が問題で特定のブラウザからリクエストが来ていない ‒ CSSの記法が問題でファイルが読み込まれていない、など • TODO：修正が必要なファイルを調査 1. 対象ブラウザでアクセスがないPathを出力 特定のブラウザだけ特定のパスが表示できていない気がする

24 都度発生する特殊な障害対応/実際にあった例 • 第三者から画像やJSを直接参照されている気がする... 1. URLでフィルタ 2. Referrerを表示

25 今後

26 実験中のこと • デプロイ後のプロセスにKibana監視を追加 • 数分後にSlackにKibanaの状態を通知 ‒ サーバ切り替わり状況 ‒ リクエスト推移 ‒ エラー状況 ‒ レスポンス時間の変化 • 数分間は自動でログを高頻度にチェック ‒ エラーが増えると自動で戻す

27 今後の課題 • 計算リソース（≒お金)と大量のデータを扱えるDBが必要 ‒ 量が多いので外部サービスに投げると高コスト • 表示（集計）に時間がかかる • 何でもできてしまう ‒ 時間泥棒…

28 ES5.0に期待していること • 高速、省データ容量化 • Keywordフィールド：ログ用にスキーマを作りやすくなった • BM25/N-Best： 検索のスコアリングが改善 • Ingest Node: インデクシング時にデータを加工できる ‒ Apacheやnginxでのログの時間単位の違い（秒？ミリ秒？）をESで吸収できそう

29 デモ

30 サーバを準備する • Elasticsearch ‒ docker run -d -p 9200:9200 --name es elasticsearch • Kibana ‒ docker run -d --link es:elasticsearch -p 5601:5601 kibana • Webserver ‒ https://github.com/bungoume/httpbin-container ‒ sudo docker run -d -p 80:80 -v /tmp/log:/log bungoume/httpbin-container • Log-sender(Fluentd) ‒ https://github.com/bungoume/log-sender-demo ‒ docker run -d --link es:elasticsearch.local -v /tmp/log:/data/log bungoume/log-sender-demo

31 リクエストしてみる • ブラウザでアクセス • HTTPieでリクエスト • OWASP ZAPでリクエスト

32 32 Questions?!