Badooでのデーモンログの収集と分析

はじめに

Badooには多数の「自作」の悪魔がいます。 それらのほとんどはCで書かれており、1つはC ++で、5つまたは6つはGoで残っています。 4つのデータセンターにある約100台のサーバーで動作します。

Badooでは、ヘルスチェックとデーモンの問題の検出は、監視部門の肩にかかっています。 Zabbixとスクリプトを使用している同僚は、サービスが実行されているかどうか、リクエストに応答するかどうか、またバージョンを監視します。 さらに、部門は、異常、突然のジャンプなどのために悪魔とそれらと連携するスクリプトの統計を分析します。



ただし、最近まで、非常に重要な部分はありませんでした。各デーモンがサーバー上のファイルにローカルで書き込むログの収集と分析です。 多くの場合、この情報は、初期段階で問題を発見したり、事後調査を行って障害の原因を理解したりするのに役立ちます。

このようなシステムを構築し、詳細を急いで共有しています。 きっとあなたの1人が同様の仕事をするでしょう、そしてこの記事を読むことは私達が犯した間違いからあなたを救います。

ツール選択

当初から、「クラウド」システムに陰影を付けています。 Badooでは、可能であればデータを提供しないのが慣例です。 人気のあるツールを分析した結果、次の3つのシステムのいずれかが適しているという結論に達しました。

• スプランク
• ELK;
• グレイログ2。

スプランク

まず、Splunkを試しました。 Splunkはターンキーシステムであり、閉鎖型の有料ソリューションであり、そのコストはシステムに着信するトラフィックに直接依存します。 すでに請求部門のデータに使用しています。 同僚はとても満足しています。



私たちはテストのためにそれらのインストールを利用し、ほとんどすぐに私たちのトラフィックが利用可能な支払い済みの制限を超えたという事実に直面しました。

別のニュアンスは、テスト中に、一部の従業員がユーザーインターフェイスの複雑さと「直感的でない」ことに不満を言うことでした。 この期間中の課金担当者は、Splunkとのコミュニケーションを既にマスターしており、問題はありませんでしたが、この事実は注目に値します。 システムを積極的に使用したい場合、素敵なインターフェイスが非常に重要になります。

Splunkの技術面では、明らかに完全に満足しました。 しかし、そのコスト、近さ、および不便なインターフェースにより、私たちはさらに先を見ていました。

ELK：Elastic Search + Logstash + Kibana

リストの次はELKでした。 ELKは、おそらく今日のログを収集および分析するための最も人気のあるシステムです。 そして、これは驚くことではありません。 無料で、シンプルで、柔軟性があり、強力です。

ELKは3つのコンポーネントで構成されています。

• 弾性検索。 Luceneエンジンに基づくデータ保存および検索システム。
• Logstash。 データ（処理される可能性がある）がElastic Searchに到達する一連の機能を備えた「パイプ」。
• キバナ。 Elastic Searchからのデータを検索および視覚化するためのWebインターフェース。

ELKの使用は非常に簡単です。公式サイトから3つのアーカイブをダウンロードし、いくつかのバイナリを解凍して実行するだけです。 このシンプルさにより、システムを数日でテストし、システムがどのように適しているかを理解できました。

そして全体的に彼女は思いついた。 技術的には、必要に応じて必要なものをすべて実装し、独自のソリューションを作成して、共通のインフラストラクチャに構築できます。

ELKが私たちに完全に合っていたという事実にもかかわらず、3番目の挑戦者がいました。

グレイログ2

一般に、Graylog 2はELKに非常によく似ています。オープンソースで、インストールが簡単で、Elastic SearchとLogstashも使用できます。 主な違いは、Graylog 2はログを収集するために特別に調整されたすぐに使用できるシステムであることです。 エンドユーザーに対する準備が整っていることから、Splunkを非常に連想させます。 ブラウザで行の解析を直接カスタマイズし、アクセスと通知を制限する機能を備えた便利なグラフィカルインターフェイスもあります。

しかし、ELKを使用すると、ニーズに合わせてカスタマイズされたはるかに柔軟なシステムを作成できるという結論に達しました。 コンポーネントを拡張、変更します。 コンストラクターとして。 私はある部分が好きではありませんでした-別の部分に置き換えられました 彼らはウォッチャーにお金を払いたくありませんでした-彼らは独自のシステムを作りました。 ELKですべての部品を簡単に取り外して交換できる場合、Graylog 2では、一部の部品をルートで切断する必要があり、一部は単に実装できないと感じました。

解決されました。 ELKで行います。

ログ配信

非常に初期の段階で、ログがコレクターに入り、ディスク上に残るように必須の要件を作成しました。 ログを収集および分析するシステムは優れていますが、どのシステムも一定の遅延を与え、失敗する可能性があり、grep、AWK、並べ替えなどの標準的なUNIXユーティリティが提供する機能を置き換えるものは何もありません。 プログラマーはサーバーに行き、そこで何が起こっているのか自分の目で確かめる機会を持つべきです。

次のようにログをLogstashに配信できます。

• ELKスイートの既存のユーティリティを使用します（logstash-forwarder、そして現在は勝っています）。 これらはディスク上のファイルを監視し、Logstashにアップロードする別個のデーモンです。
• PHPログを配信するLSDという名前で独自の開発を使用してください。 実際、これはファイルシステム内のログファイルを監視し、それらをどこかにアップロードする別個のデーモンでもあります。 一方で、LSDは膨大な数のサーバーから膨大な数のログをアップロードする際に発生する可能性のあるすべての問題を考慮に入れて解決しましたが、システムはPHPスクリプトに対して「調整」されすぎています。 終了する必要があります。
• ディスクへの書き込みと並行して、UNIXの世界のsyslog標準にログを書き込みます。

後者の欠点にもかかわらず、このアプローチは非常に簡単でしたので、試してみることにしました。

建築

サーバーとrsyslogd

システム管理者と一緒に、私たちにとって妥当と思われるアーキテクチャをスケッチしました：各サーバーに1つのrsyslogdデーモン、サイトに1つのメインrsyslogdデーモン、サイトに1つのLogstash、そしてモスクワに近い1つのElastic Searchクラスターを配置しました。 。 プラハのデータセンターへ。

写真では、サーバーの1つは次のようになりました。



なぜなら Badooはいくつかの場所でdockerを使用します。組み込みツールを使用して、コンテナ内に/ dev / logソケットをスローすることを計画しました。

最終的なチャートは次のようなものでした：



上記で考案されたスキームは、最初はデータ損失に対して非常に耐性がありました。各rsyslogdデーモンは、メッセージをさらに送信できない場合、ディスクに保存し、「次の」動作時に送信します。

最初のrsyslogデーモンが機能しなかった場合にのみ、データが失われました。 しかし、その瞬間、私たちはこの問題にあまり注意を払いませんでした。 それでも、ログは非常に重要な情報ではないため、最初から多くの時間を費やす必要があります。

ログ行の形式とLogstash

Logstashは、行が送信されるデータのパイプです。 内部では、それらは解析され、インデックス作成の準備ができたフィールドとタグの形式でElastic Searchに移動します。

ほとんどすべてのサービスは、独自のlibangelライブラリを使用して構築されています。つまり、同じログ形式を持ち、次のようになります。

Mar 04 04:00:14.609331 [NOTICE] <shard6> <16367> storage_file.c:1212 storage___update_dump_data(): starting dump (threaded, update) 

この形式は、変更されていない一般的な部分と、ロギング用の関数の1つを呼び出すときにプログラマーが自分で設定する部分で構成されます。

一般的な部分では、日付、マイクロ秒付きの時刻、ログレベル、ラベル、PID、ソースのファイル名と行番号、関数の名前が表示されます。 最も一般的なもの。

Syslogは、時間、PID、サーバーのホスト名、いわゆるidentといった情報を自身からこのメッセージに追加します。 これは通常、プログラムの名前にすぎませんが、何でも渡すことができます。

このidentを標準化し、名前、セカンダリ名、およびデーモンのバージョンをそこに渡します。 たとえば、 meetmaker-ru.mlan-1.0.0です。 したがって、異なるデーモンのログ、異なるタイプの1つのデーモン（国、レプリカなど）のログを区別し、実行中のデーモンのバージョンに関する情報を取得できます。

このようなメッセージの分析は非常に簡単です。 この記事では構成ファイルの一部を引用しませんが、それはすべて、正規の正規表現を使用した文字列の部分の段階的な「食い込み」および解析に帰着します。

解析のいくつかの段階が失敗した場合、特別なタグをメッセージに追加します。これにより、後でそのようなメッセージを見つけてその番号を監視できます。

時間の分析に関する言及。 さまざまなオプションを考慮しようとしましたが、デフォルトのメッセージ時間はlibangelメッセージからの時間になります。 基本的に、このメッセージが生成された時間。 何らかの理由でこの時間が見つからなかった場合、syslogから時間を取ります。 メッセージが最初のローカルsyslogデーモンに送られた時間。 何らかの理由でこの時間も利用できない場合、メッセージの時間はLogstashでこのメッセージを受信した時間になります。

結果のフィールドは、インデックス作成のためにElastic Searchに送られます。

Elasticsearch

Elastic Searchは、複数のノードが1つのネットワークに結合されて連携する場合、クラスターモードでの動作をサポートします。 インデックスごとに別のノードへのレプリケーションを構成できるため、一部のノードに障害が発生してもクラスターは動作し続けます。

フェールオーバークラスター内のノードの最小数は3で、最初の奇数は1より大きいです。 これは、内部アルゴリズムの操作のために、クラスターを部分に分割するときに、大部分を分離できることが必要であるという事実によるものです。 偶数のノードはこれには適していません。

Elastic Searchクラスターに3つのサーバーを割り当て、図のように各インデックスが1つのレプリカを持つように構成しました。



このようなアーキテクチャでは、クラスターノードのいずれかの障害は致命的ではなく、クラスターにアクセスできなくなります。

フォールトトレランス自体に加えて、このようなスキームでは、Elastic Search自体を更新すると便利です。一方のノードを停止し、それを更新し、開始し、他方を更新します。

Elastic Searchにログを正確に保存するという事実により、すべてのデータを1日ごとに簡単にインデックスに分割できます。 このようなパーティションには、いくつかの利点があります。

• サーバーのディスク容量が不足した場合、古いデータを削除するのは非常に簡単です。 これは簡単な操作であり、さらに、古いデータを削除する既製のキュレーターツールがあります。
• 1日以上の間隔での検索中に、検索を並行して実行できます。 さらに、1つのサーバーと複数のサーバーの両方で並行して実行できます。

既に述べたように、十分なディスク容量がない場合に古いインデックスを自動的に削除するようにキュレーターを設定しました。

Elastic Searchのセットアップでは、Javaと、単にLuceneが内部で使用されるという事実の両方に関連する多くの微妙な点があります。 しかし、これらの微妙な点はすべて公式文書と多数の記事の両方で説明されているので、深く掘り下げません。 Elastic Searchサーバーでは、Javaヒープと外部ヒープ（Luceneで使用される）の両方にメモリを割り当てることを覚えておく必要があることを簡単に述べておきます。ディスク上。

キバナ

話すことは何もありません:-)配信され、動作します。 幸いなことに、最新バージョンでは、開発者は設定でタイムゾーンを変更する機能を追加しました。 以前は、ユーザーのローカルタイムゾーンがデフォルトで使用されていましたが、これは非常に不便です。 あらゆる場所のサーバーで常にUTCであり、その上での通信に慣れています。

通知システム

ログ収集システムの非常に重要な部分と主な要件の1つは、通知システムの可用性でした。 ルールまたはフィルターに基づいて、詳細を確認できるページへのリンクでトリガーされるルールを通知する文字を送信するシステム。

ELKの世界には2つの類似した既製製品がありました。

• Elastic社のウォッチャー 。
• Elastalert by Yelp

Watcherは、アクティブなサブスクリプションを必要とする閉じたElastic製品です。 Elastalertは、Pythonで書かれたオープンソース製品です。 以前と同じ理由で、私たちはすぐにWatcherを廃止しました-私たちに拡大して適応することの近さと複雑さ。 テストによると、Elastalertはクールな製品であることが判明しましたが、いくつかの欠点もありました（ただし、それほど重要ではありません）。

• Pythonで書かれています。 Pythonは、高速な「ニーハイ」スクリプトを作成するための言語として気に入っていますが、実稼働環境で最終製品として見たくはありません。
• イベントに応じてシステムが送信する文字を作成する可能性は、完全に初歩的なものです。 そして、他の人にこのシステムを使いたいという欲求があれば、文章の美しさと便利さは非常に重要です。

Elastalertで遊んでそのソースコードを調べたので、プラットフォーム部門を使用してPHPで製品を書くことにしました。 その結果、Denis Karasik Battlecatは2週間にわたって「調整」された製品を作成しました。これはバックオフィスに統合され、必要な機能のみを備えています。





各ルールについて、システムはKibanaに基本的なダッシュボードを自動的に作成します。このリンクはレターに記載されます。 リンクをクリックすると、通知で指定された期間のメッセージとスケジュールが正確に表示されます。

「熊手」

この段階で、システムの最初のリリースの準備が整い、機能し、使用できるようになりました。 しかし、私たちが約束したように、「熊手」はもうすぐではありませんでした。

問題1（syslog + docker）

syslogデーモンとプログラムの間の標準的な通信方法は、unix socket / dev / logです。 前述のように、 標準の docker ツールを使用してコンテナにそれを投げました。 syslogデーモンをリロードする必要があるまで、このバンドルは正常に機能しました。

どうやら、ディレクトリではなく特定のファイルが転送された場合、ホストシステムでファイルを削除または再作成すると、コンテナ内でアクセスできなくなります。 syslogデーモンを再起動すると、Dockerコンテナからのログが終了することがわかりました。

ディレクトリ全体を転送すると、内部に問題なくUNIXソケットが存在し、デーモンを再起動しても何も壊れません。 しかし、libcはソケットが/ dev / logにあることを想定しているため、このすべての富を構成することはより複雑になります。

検討した2番目のオプションは、UDPまたはTCPを使用してログを送信することです。 しかし、これは前のケースと同じ問題です：libcは/ dev / logにしか書き込むことができません。 syslogクライアントを作成する必要がありますが、この段階ではこれを行いたくありませんでした。

最終的に、各コンテナで1つのsyslogデーモンを実行し、標準のlibc openlog（）/ syslog（）関数を使用して/ dev / logに書き込みを続けることにしました。

これは大きな問題ではありませんでした システム管理者は、1つのデーモンのみを起動するのではなく、各コンテナでinitシステムを引き続き使用します。

問題2（syslogのブロック）

開発クラスターで、デーモンの1つが定期的にハングすることに気付きました。 デーモンの内部ウォッチドッグをオンにすると、いくつかのバックトレースが得られ、syslog（）-> write（）でデーモンがハングすることがわかりました。

 ==== WATCHDOG ==== tag: IPC_SNAPSHOT_SYNC_STATE start: 3991952 sec 50629335 nsec now: 3991953 sec 50661797 nsec Backtrace: /lib64/libc.so.6(__send+0x79)[0x7f3163516069] /lib64/libc.so.6(__vsyslog_chk+0x3ba)[0x7f3163510b8a] /lib64/libc.so.6(syslog+0x8f)[0x7f3163510d8f] /local/meetmaker/bin/meetmaker-3.1.0_2782 | shard1: running(zlog1+0x225)[0x519bc5] /local/meetmaker/bin/meetmaker-3.1.0_2782 | shard1: running[0x47bf7f] /local/meetmaker/bin/meetmaker-3.1.0_2782 | shard1: running(storage_save_sync_done+0x68)[0x47dce8] /local/meetmaker/bin/meetmaker-3.1.0_2782 | shard1: running(ipc_game_loop+0x7f9)[0x4ee159] /local/meetmaker/bin/meetmaker-3.1.0_2782 | shard1: running(game+0x25b)[0x4efeab] /local/meetmaker/bin/meetmaker-3.1.0_2782 | shard1: running(service_late_init+0x193)[0x48f8f3] /local/meetmaker/bin/meetmaker-3.1.0_2782 | shard1: running(main+0x40a)[0x4743ea] /lib64/libc.so.6(__libc_start_main+0xf5)[0x7f3163451b05] /local/meetmaker/bin/meetmaker-3.1.0_2782 | shard1: running[0x4751e1] ==== WATCHDOG ==== 

libcソースをすばやくダウンロードし、syslogクライアントの実装を確認したところ、syslog（）関数は同期であり、rsyslog側の遅延がデーモンに影響することがわかりました。

これで何かをする必要がありましたが、早ければ早いほど良いです。 しかし、時間がありませんでした...

数日後、私たちは現代建築の最も不快なレーキであるカスケード失敗に踏み出しました。



Rsyslogはデフォルトで設定されているため、何らかの理由で内部キューがいっぱいになると、「スロットル」（eng。Throttle）が開始されます。 新しいメッセージの「自分の記録」を遅くします。

プログラマーの監視により、テストサーバーの1つが大量のメッセージをログに送信し始めたことが判明しました。 Logstashはこのようなストリームに対処できませんでした。メインのrsyslogキューがいっぱいで、他のrsyslogからのメッセージを非常にゆっくりと読み取りました。 このため、他のrsyslogのキューもオーバーフローし、デーモンからのメッセージの読み取りが非常に遅くなりました。

そして、悪魔は、上で言ったように、/ dev / logに同期して、タイムアウトなしで書き込みます。
結果は予測可能です。フラッディングテストデーモンが1つあるため、少なくともかなりの頻度でsyslogに書き込むすべてのデーモンの速度が低下し始めました。

もう1つの間違いは、潜在的な問題についてシステム管理者に通知しなかったことであり、理由を見つけてrsyslogを無効にするのに1時間以上かかりました。

このレーキを踏んだのは私たちだけではありません。 そして、rsyslogだけではありません 。 デーモンのイベントループでの同期呼び出しは、許容できない贅沢です。

いくつかのオプションがありました。

• syslogから脱出します。 他のオプションの1つに戻ります。これは、デーモンがディスクに書き込みを行っており、すでに他のデーモンがディスクから完全に独立して読み取りを行っていることを示しています。
• syslogへの同期書き込みを続けますが、別個のスレッドで行います。
• syslogクライアントを作成し、UDPを介してsyslogにデータを送信します。

最も正しいオプションはおそらく最初のものです。 しかし、私たちはそれに時間を無駄にしたくなかったので、すぐに3つ目を作りました。 UDP経由でsyslogへの書き込みを開始しました。

Logstashに関しては、2つの起動パラメーターがすべての問題を解決しました。ハンドラーの数と同時に処理される行の数を増やすことです（ -w 24 -b 1250 ）。

今後の計画

近い将来、悪魔のダッシュボードを作成してください。 既存の機能といくつかの新しい機能を組み合わせたこのようなダッシュボード：

• デーモンの状態（「トラフィックライト」）、基本的な統計情報を表示します。
• ログのエラーおよび警告の行数のグラフ、それらの表示;
• トリガーされたアラートシステムルール。
• 問題のあるサービスまたはリクエストを表示するSLAモニタリング（レイテンシーレスポンスモニタリング）。
• デーモンログからのさまざまな段階の選択。 たとえば、ダウンロードのどの段階にあるか、ダウンロード時間、いくつかの定期的なプロセスの期間などのマーク。

私の意見では、このようなダッシュボードの存在は、マネージャー、プログラマー、管理者、モニターに訴えるでしょう。

おわりに

すべてのデーモンのログを収集し、それらを便利に検索し、グラフと視覚化を構築し、問題をメールで通知できるようにするシンプルなシステムを構築しました。

システムの成功は、その存在中に、まったく発見できなかった、または長い時間後に発見された問題を迅速に発見し、他のチームがインフラストラクチャを使用し始めているという事実によって証明されます。

負荷について話すと、1日あたりログが毎秒600〜2000行で、最大1万行の周期的なバーストが発生します。 システムは問題なくこの負荷を消化します。



日次インデックスのサイズは、数十ギガバイトから数百ギガバイトまでさまざまです。



このシステムには欠点があり、何か別のことを行うことで「レーキ」を回避できると言う人もいます。 これは本当です。 しかし、私たちはプログラミングのためにプログラミングをしているわけではありません。 私たちの目標は、合理的に最小限の時間で達成され、システムは非常に柔軟であるため、将来私たちと一致しない部分は非常に簡単に改善または変更できます。

Marco Kevats、C / C ++開発部門のプログラマー