バックエンドでの便利なロギング。Yandexレポート

何かがいつも計画通りに進まない。「何が壊れているのか」、「なぜ遅くなるのか」という質問に答える必要があります。と「なぜこれまで見なかったの？」例として単純なアプリケーションを使用するDaniilGalievzefiriorYandex.Travelから、これらの質問に答える方法と、これに役立つツールを紹介しました。便利なインターフェイスで、ロギングの設定、トレースの添付、エラーの展開などを行います。



- 始めましょう。便利なロギングと、アプリケーションとそのライフサイクルを使いやすくするために展開できるロギングに関するインフラストラクチャについて説明します。







私たちは何をしますか？小さなアプリケーション、つまりスタートアップを構築します。次に、基本的なロギングを実装します。これはレポートのごく一部であり、Pythonがすぐに提供するものです。そして最大の部分は、デバッグ、ロールアウト、およびそれらを解決するためのツールの間に発生する典型的な問題を分析することです。



小さな免責事項：ペンやロケールなどの単語を使用します。説明させてください。「ハンドル」はおそらくyandexスラングであり、API、http、gRPC API、またはAPUより前のその他の文字の組み合わせを示します。「ロケール」は、私がラップトップで開発するときです。私がコントロールしていないすべての言葉について話したようです。

書店アプリケーション

はじめましょう。私たちのスタートアップは書店です。このアプリケーションの主な機能は、本を販​​売することです。それが私たちがやりたいことのすべてです。それから少し詰めます。アプリケーションはFlaskで作成されます。すべてのコードスニペット、すべてのツールは汎用であり、Pythonから抽象化されているため、ほとんどのアプリケーションに統合できます。しかし、私たちの話では、それはフラスコになります。



キャラクター：私、開発者、マネージャー、そして私の最愛の同僚エラスト。偶然の一致です。







構造について少しお話しましょう。これは、マイクロサービスアーキテクチャアプリケーションです。最初のサービスはBooksです。これは、本のメタデータを備えた本のストレージです。 PostgreSQLデータベースを使用しています。 2番目のマイクロサービスは、ユーザーの注文に関するメタデータを格納する配信マイクロサービスです。キャビネットは、キャビネットのバックエンドです。フロントエンドはありません。レポートでは必要ありません。内閣は、本サービスと配達サービスからの要求、データを集約します。







これらのサービスのハンドルであるAPIBooksのコードを簡単に紹介します。このハンドルは、データベースからデータを取得してシリアル化し、JSONに変換して返します。







さらに進んでみましょう。配達サービス。ハンドルはまったく同じです。データベースからデータを取得し、シリアル化して送信します。







そして最後のノブはキャビネットノブです。コードが少し異なります。キャビネットハンドルは、配信サービスとブックサービスからの要求データを処理し、応答を集約して、ユーザーに注文を渡します。すべて。アプリケーションの構造をすぐに理解しました。

アプリケーションでの基本的なロギング

それでは、私たちが見た基本的なロギングについて話しましょう。用語から始めましょう。







Pythonは私たちに何を与えますか？ 4つの基本的な主要エンティティ：



-Logger、コードにログインするためのエントリポイント。ある種のロガーを使用し、logging.INFOを記述します。それだけです。あなたのコードは、メッセージがどこに行き、次に何が起こったのかについて何も知りません。 Handlerエンティティはすでにこれを担当しています。



-ハンドラーはメッセージを処理し、送信先を決定します。標準出力、ファイル、または他の人のメールです。



-フィルターは、2つの補助エンティティの1つです。ログからメッセージを削除します。もう1つの一般的な使用例は、データの詰め込みです。たとえば、投稿に属性を追加する必要があります。フィルタはこれにも役立ちます。



--Formatterは、メッセージを目的の形式にします。







ここで用語を終了しました。基本クラスを使用して、Pythonで直接ロギングに戻ることはありません。ただし、これは3つのサービスすべてに展開されるアプリケーションの構成例です。私たちにとって2つの主要な重要なブロックがあります：フォーマッターとハンドラーです。フォーマッターの場合、メッセージがどのように表示されるかについてのテンプレートである例がここにあります。



ハンドラーでは、logging.StreamHandlerが使用されていることがわかります。つまり、すべてのログを標準出力にダンプします。以上です。これで完了です。

問題1.ログが散在している

問題に移ります。まず、最初の問題は、ログが散在していることです。



少しコンテキスト。アプリケーションを作成しました。キャンディーはすでに準備ができています。私たちはそれでお金を稼ぐことができます。現在、本番環境に展開しています。もちろん、複数のサーバーがあります。控えめな見積もりによると、最も複雑なアプリケーションでは、サービスごとに約3〜4台の車が必要です。



さて、質問です。マネージャーが駆け寄ってきて、「そこで壊れた、助けて！」と尋ねます。あなたは走っている。すべてがあなたのために記録されます、それは素晴らしいです。あなたは最初のタイプライターに行きます、見てください-あなたの要求のためにそこには何もありません。 2台目の車に行きます-何もありません。等々。これは悪いです、それはどうにかして解決されなければなりません。







見たい結果を形式化してみましょう。ログを1か所にまとめたい。これは単純な要件です。少しクールなのは、ログを検索したいということです。つまり、はい、それは1つの場所にあり、リッピングする方法を知っていますが、いくつかのツール、単純なグラプ以外のクールな機能があればクールです。



そして、私は書きたくありません。コードを書くのが大好きなエラストです。私はそれについて話していません、私はすぐに製品を作りました。つまり、追加のコードを減らして、1つまたは2つのファイル、行で処理するだけです。







使用できるソリューションはElasticsearchです。それを上げてみましょう。 Elasticsearchの利点は何ですか？これはログ検索インターフェイスです。箱から出してすぐにインターフェースがあります。これはあなたのためのコンソールではありませんが、唯一の保管場所です。つまり、主な要件を満たしています。サーバーに行く必要はありません。



私たちの場合、それはかなり単純な統合であり、最近のリリースでは、Elasticsearchにはほとんどの統合を担当する新しいエージェントがあります。彼らはそこで彼ら自身の統合を見ました。とてもかっこいい。私は以前に講演を書き、同じように簡単にfilebeatを使用しました。ログの場合は簡単です。



Elasticsearchについて少し。宣伝したくありませんが、多くの追加機能があります。たとえば、すばらしいのは、箱から出してすぐにフルテキストのログ検索を行うことです。とてもかっこいいですね。今のところ、これらの利点は私たちにとって十分です。固定します。







まず、ログをElasticsearchに送信するエージェントをデプロイする必要があります。 Elasticsearchにアカウントを登録してから、docker-composeに追加します。 docker-composeがない場合は、ハンドルまたはシステムでレイズできます。この場合、次のコードブロックが追加され、docker-composeに統合されます。これで、サービスが構成されました。そして、volumesブロックにfilebeat.yml構成ファイルが表示されます。







filebeat.ymlの例を次に示します。ここでは、近くで回転しているドッカーコンテナのログの自動検索を設定しました。これらのログの選択はカスタマイズされています。条件によって、コンテナにラベルを設定してハングアップすることができます。これに応じて、ログは特定のコンテナからのみ送信されます。プロセッサ：add_docker_metadataブロックは単純です。 dockerコンテキストのログに関するもう少し情報をログに追加します。オプションですが、かっこいいです。







何がありますか？それが私たちが書いたすべて、すべてのコード、とてもクールです。同時に、すべてのログを1か所にまとめ、インターフェイスがあります。ログを検索できます。これが検索バーです。それらは配達されます。また、ライブでオンにして、ストリームがインターフェイスのログに飛ぶようにすることもできます。







ここで私自身が尋ねたでしょう：なぜ、どうやって何かを座屈させるのですか？ログ検索とは何ですか、そこで何ができますか？



はい、このアプローチの箱から出して、テキストログがある場合、小さなギャグがあります。たとえば、メッセージ：ユーザーなどのテキストでリクエストを設定できます。これにより、usersサブストリングを持つすべてのログが出力されます。アスタリスク、他のほとんどのunixワイルドカードを使用できます。しかし、これだけでは不十分なようです。できるだけ早くNginxでウォームアップできるように、もっと難しくしたいと思います。







Elasticsearchから少し離れて、Elasticsearchではなく、別のアプローチでそれを実行してみましょう。構造ログについて考えてみましょう。これは、各ログエントリが単なるテキスト行ではなく、サードパーティシステムのいずれかが既製のオブジェクトを取得するためにシリアル化できる属性を持つシリアル化されたオブジェクトである場合です。



これの利点は何ですか？統一されたデータ形式です。はい、オブジェクトは異なる属性を持つことができますが、外部システムはJSONを読み取り、ある種のオブジェクトを受け取ることができます。



ある種のタイピング。これにより、他のシステムとの統合が簡素化されます。デシリアライザーを作成する必要がありません。そして、デシリアライザーだけが別のポイントです。アプリケーションで無作法なテキストを書く必要はありません。例：「ユーザーは、そのようなIDスペシャリストを、そのような注文で持ってきました。」そして、これはすべて毎回書く必要があります。



気になりました。 「リクエストが届きました」と書きたい。さらに：「まあまあ、まあまあ、まあまあ」、非常にシンプルで、非常にITスタイル。







次へ移りましょう。同意しましょう。JSON形式でログインします。これは単純な形式です。 Elasticsearchはすぐにサポートされます。filebeatはシリアル化してファイリングを試みます。それほど難しいことではありません。まず、設定ファイルをpythonjsonloggerライブラリからJSONFormatterフォーマッタブロックに追加します。ここに構成を保存します。これは、システム内の別の場所である可能性があります。次に、format属性で、オブジェクトに追加する属性を渡します。



以下のブロックは、filebeat.ymlに追加される構成ブロックです。箱から出して、JSONログを解析するためのfilebeatのインターフェースがあります。とてもかっこいい。それがすべてです。このために他に何も書く必要はありません。そして今、あなたのログはオブジェクトのように見えます。







Elasticsearchで何を取得しましたか？インターフェイスでは、ログが個別の属性を持つオブジェクトになっていることがすぐにわかります。これにより、検索、フィルターの作成、複雑なクエリの実行を行うことができます。







まとめましょう。これで、ログに構造ができました。それらは使いやすく、インテリジェントなクエリを書くために使用できます。 Elasticsearchは、これらすべての属性を解析するため、この構造を認識しています。また、Elasticsearchのインターフェイスであるkibanaでは、Elasticsearchが提供する特殊なクエリ言語を使用してこのようなログをフィルタリングできます。



そして、それはパドリングよりも簡単です。Grepはかなり複雑でクールな言語を持っています。書くべきことがたくさんあります。キバナでは多くのことが簡単になります。これで整理しました。

問題2.ブレーキ

次の問題はブレーキです。マイクロサービスアーキテクチャでは、いつでもどこでもブレーキがあります。







ここに少しコンテキストがあります、私はあなたに話をします。私たちのプロジェクトの主人公であるマネージャーが私に駆け寄って来て、こう言います。ダーニャ、救って、助けて！」



まだ何も知りません。Elasticsearchのログにアクセスします。しかし、実際に何が起こったのかをお話ししましょう。







Erastが機能を追加しました。本では、作者のIDではなく、彼の名前がインターフェイスに表示されるようになりました。とてもかっこいい。彼は次のコードでそれを行いました。小さなコードで、複雑なことは何もありません。何がうまくいかない可能性がありますか？



SQLAlchemyや他のORMでもこれを行うことはできないと、訓練された目で言うことができます。ループ内の小さなサブクエリでデータベースに移動しないように、プリキャッシュなどを実行する必要があります。不快な問題。そんな間違いは全然できないようです。



言っておくけど。私は経験がありました。Djangoを使用し、プロジェクトにカスタムのプリキャッシュを実装しました。すべてが何年もの間うまくいった。ある時点で、Erastと私は決めました：時代に遅れずについていきましょう、Djangoを更新してください。当然、Djangoはカスタムキャッシュについて何も知らず、インターフェイスが変更されました。プリカシュは静かに落ちた。これはテストでは検出されませんでした。同じ問題で、捕まえるのはもっと難しかったです。



どうしたの？どうすれば問題の解決を手伝うことができますか？







ブレーキを見つける問題を解決し始める前に私がしたことをお話ししましょう。



私が最初にすることはElasticsearchに行くことです、私たちはすでにそれを持っています、それは助けになります、サーバーの周りを走る必要はありません。キャビネットのログを探して、ログに移動します。長いクエリが見つかりました。私はそれをラップトップで再生し、それが抑制しているのはオフィスではないことを確認します。本を遅くします。



Booksのログに出くわし、問題のあるクエリを見つけました。実際、すでにそれがあります。ラップトップでも同じように本を複製します。非常に複雑なコード-私は何も理解していません。デバッグを始めています。タイミングをとるのはかなり難しいです。どうして？ SQLAlchemyでこれを内部的に決定することは非常に困難です。私はカスタムタイムロガーを作成し、問題をローカライズして修正します。







それは私を傷つけました。難しい、不快。私は泣いた。問題を見つけるこのプロセスをより速く、より便利にしたいと思います。



問題を形式化しましょう。私たちのログは無関係なイベントのログであるため、速度が低下しているものをログで検索することは困難です。実行されたコードのブロック数を示すカスタムタイマーを作成する必要があります。さらに、外部システムのタイミングをログに記録する方法が明確ではありません。たとえば、ORMやリクエストライブラリなどです。タイマーを内部または何らかのラッパーに埋め込む必要がありますが、内部で速度が低下する理由はわかりません。複雑。







私が見つけた良い解決策はイエーガーです。これはopentracingプロトコルの実装なので、トレースを実装しましょう。



イエーガーは何を与えますか？これは、検索クエリを備えたユーザーフレンドリーなインターフェイスです。長いクエリをフィルタリングすることも、タグでフィルタリングすることもできます。リクエストの流れを視覚的に表現した、とても美しい写真です。少し後でお見せします。



タイミングは箱から出してログアウトされます。あなたは彼らと何もする必要はありません。実行されているカスタムブロックの量を確認する必要がある場合は、Jaegerが提供するタイマーでラップできます。とても快適です。







インターフェイスで問題を見つけて、そこでローカライズすることがどのように可能であったかを見てみましょう。 Jaegerインターフェースに入ります。これが私たちのリクエストの様子です。アカウントまたは他のサービスのリクエストを検索できます。長いクエリはすぐにフィルタリングされます。私たちは長いものに興味があり、ログから見つけるのは非常に困難です。私たちは彼らのリストを取得します。







このクエリに該当すると、SQLサブクエリの大きな足がかりが表示されます。それらが時間内にどのように実行されたか、どのコードブロックが何を担当したかを明確に確認できます。とてもかっこいい。さらに、私たちの問題の文脈では、これはログ全体ではありません。 2、3枚下にスライドする大きな足布がまだあります。 Jaegerで問題をかなり迅速にローカライズしました。問題を解決した後、イエーガーが提供するコンテキストは私たちに何を助けることができますか？







Jaegerログ、たとえば、SQLクエリ：どのクエリが繰り返されているかを確認できます。とても速くてかっこいい。







私たちは問題を解決し、すぐにイエーガーですべてが順調であることを確認しました。同じクエリで、サブクエリがないことを確認します。どうして？同じリクエストをチェックし、タイミングを確認するとします。Elasticsearchでリクエストが実行された時間を調べます。次に、時間を確認します。ただし、これはサブクエリがなかったことを保証するものではありません。そして、ここで私たちはそれを見る、かっこいい。







イエーガーを実装しましょう。多くのコードは必要ありません。 Flaskのopentracingの依存関係を追加します。次に、実行しているコードについて説明します。



コードの最初のブロックは、Jaegerクライアントのセットアップです。



次に、Flask、Django、または統合されているその他のフレームワークとの統合を設定します。



install_all_patchesはコードの最後の行であり、最も興味深いものです。MySQL、Postgres、リクエストライブラリとやり取りすることで、ほとんどの外部統合にパッチを適用します。これらすべてにパッチを適用しているため、Jaegerインターフェイスでは、SQLを使用したすべてのクエリと、必要なサービスがどのサービスにアクセスしたかがすぐに表示されます。とてもかっこいい。そして、あなたは多くを書く必要はありませんでした。install_all_patchesを作成しました。魔法！



何がありますか？これで、ログからイベントを収集する必要がなくなりました。私が言ったように、ログは異なるイベントです。イエーガーでは、これはあなたがその構造を見る一つの大きなイベントです。Jaegerを使用すると、アプリケーションのボトルネックを見つけることができます。長いクエリを検索するだけで、何が問題になっているのかを分析できます。

問題3.エラー

最後の問題はエラーです。はい、私は狡猾です。アプリケーションのエラーを取り除くのは手伝いませんが、次に何ができるかを説明します。







環境。次のように言うことができます。「Danya、エラーをログに記録しています。500件のアラートがあり、設定しました。なんでしょう？ログに記録し、ログに記録し、ログに記録してデバッグします。



ログからエラーの重要性がわかりません。重要性は何ですか？ここに、1つのクールなエラーと、データベースへの接続のエラーがあります。ベースがフロップしました。この間違いはそれほど重要ではないことをすぐに確認したいと思います。時間がない場合は無視して、より重要な間違いを修正してください。



エラー率は、それをデバッグするのに役立つコンテキストです。エラーを追跡する方法は？続けましょう。1か月前にミスがありましたが、今度は再び表示されます。すぐに解決策を見つけて修正するか、リリースの1つと外観を比較したいと思います。







これが良い例です。 Jaegerとの統合を見たとき、APIを少し変更しました。アプリケーションの応答の形式を変更しました。このエラーが発生しました。しかし、なぜ私がキーを持っておらず、注文オブジェクトにたくさんあるのかは明確ではなく、私を助けるものは何もありません。同様に、ここでエラーを確認し、それを再現して自分でキャッチします。







歩哨を実装しましょう。これは、同様の問題を解決し、エラーのコンテキストを見つけるのに役立つバグトラッカーです。歩哨開発者によって維持されている標準ライブラリを利用してください。 4行のコードで、それをアプリケーションに追加します。すべて。







途中で何をしましたか？これは、プロジェクトごとにグループ化してフォローできるエラーのあるダッシュボードです。エラーログの膨大なフットクロスは、同一の類似したものにグループ化されます。それらに関する統計が提供されます。また、インターフェイスを使用してこれらのエラーに対処することもできます。







私たちの例を見てみましょう。 KeyErrorに陥る。エラーのコンテキスト、orderオブジェクトに含まれていたもの、存在しなかったものがすぐにわかります。 Deliveryアプリケーションが新しいデータ構造を提供してくれたことがすぐにわかります。キャビネットは単にこれの準備ができていません。







私がリストしたもの以外に歩哨は何を与えますか？正式にしましょう。



これは、それらを探すことができるエラーストアです。このための便利なツールがあります。エラーのグループ化があります-プロジェクトごと、類似性ごと。 Sentryは、さまざまなトラッカーとの統合を提供します。つまり、間違いを監視し、それらを処理することができます。タスクをコンテキストに追加するだけで、それだけです。これは開発に役立ちます。



エラー統計。繰り返しますが、これはリリースのロールアウトと比較するのは簡単です。セントリーはこれであなたを助けます。エラーの横で発生した同様のイベントも、エラーの原因を見つけて理解するのに役立ちます。







まとめましょう。シンプルでありながらニーズを満たすアプリケーションを作成しました。それはあなたがそのライフサイクルでそれを開発し維持するのを助けます。私たちは何をしましたか？ 1つのリポジトリにログを収集しました。これは私たちに別の場所でそれらを探さない機会を与えてくれました。さらに、ログとサードパーティの機能であるツールで検索できるようになりました。



統合トレース。これで、アプリケーションのデータフローを視覚的に監視できます。



また、エラーを処理するための便利なツールを追加しました。どんなに頑張っても、アプリケーションに含まれます。しかし、私たちはそれらをより速くそしてより良く修正します。



他に何を追加できますか？アプリケーション自体の準備ができており、リンクがあり、それがどのように行われるかを確認できます。すべての統合はそこで発生します。たとえば、Elasticsearchまたはトレースとの統合。入って見てください。



私がカバーする時間がなかったもう一つのクールなことはrequests_idです。トレースで使用されるtrace_idとほとんど違いはありません。しかし、私たちはrequests_idに責任があり、これが最も重要な機能です。マネージャーはrequests_idですぐに私たちのところに来ることができ、私たちは彼を探す必要はありません。私たちはすぐに問題の解決を開始します。とてもかっこいい。



また、実装したツールはオーバーヘッドであることを忘れないでください。これらは、すべてのアプリケーションで対処する必要がある問題です。私たちのすべての統合を無意識のうちに実装し、あなたの生活を楽にしてから、抑制アプリケーションをどうするかを考えることはできません。



見てみな。それがあなたに影響を与えないのなら、かっこいい。あなたはプラスを得ただけで、ブレーキの問題を解決しません。これを忘れないでください。聞いてくれてありがとう。