NodeJSアプリケーションで読み取り可能なログを整理しようとすると、何が一番イライラしますか? 個人的には、トレースIDを作成するための健全な成熟した標準がないことに非常に悩まされています。 この記事では、トレースIDを作成するためのオプションについて説明し、 継続ローカルストレージまたはCLSがどのように機能するかの指を見て、すべてのロガーですべてを取得するためにプロキシの強さを求めます。
NodeJSで各リクエストのトレースIDの作成に問題があるのはなぜですか?
マンモスがまだ地球を歩いていた昔、昔、昔は、すべてすべてのサーバーがマルチスレッド化され、リクエストに対して新しいスレッドを作成していました。 このパラダイムのフレームワーク内では、トレースIDの作成は簡単です。 スレッドローカルストレージやTLSなどがあり、このストリーム内のすべての関数で利用可能なデータをメモリに格納できます。 リクエストの処理の開始時に、ランダムトレースIDを生成し、TLSに入れて、それを任意のサービスで読み取り、それで何かを行うことができます。 問題は、NodeJSではこれが機能しないことです。
NodeJSはシングルスレッドです(完全にではありませんが、ワーカーの外観を考えると、トレースIDの問題のフレームワーク内で、ワーカーは何の役割も果たしません)。TLSを忘れることができます。 ここでパラダイムは異なります-同じスレッド内で多数の異なるコールバックをジャグリングし、関数が非同期を実行したい場合は、この非同期リクエストを送信し、キュー内の別の関数にプロセッサ時間を与えます内部では、 この一連の記事を読むことをお勧めします)。 NodeJSがどのコールバックをいつ呼び出すかをどのように理解するかを考えると、それぞれに特定のIDが必要であると想定できます。 さらに、NodeJSには、これらのIDへのアクセスを提供するAPIもあります。 それを使用します。
古代、マンモスは絶滅しましたが、人々は中央下水の利点をまだ知りませんでした(NodeJS v0.11.11) addAsyncListenerがありました 。 それに基づいて、 Forrest Norvellは継続ローカルストレージまたはCLSの最初の実装を作成しました。 しかし、このAPI(私はaddAsyncLustenerについて話している)が長命を命じたので、それがどのように機能したかについては語りません。 彼はすでにNodeJS v0.12で亡くなりました。
NodeJS 8より前は、非同期イベントのキューを追跡する公式の方法はありませんでした。 最後に、バージョン8では、NodeJS開発者が正義を取り戻し 、 async_hooks APIを提供しました 。 async_hooksの詳細を知りたい場合は、 この記事を読むことをお勧めします。 async_hooksに基づいて、以前のCLS実装のリファクタリングが行われました。 ライブラリはcls-hookedと呼ばれます。
ボンネットの下のCLS
一般的に、CLS操作スキームは次のように表すことができます。
もう少し詳しく分析してみましょう。
- 典型的なExpress Webサーバーがあるとします。 最初に、新しいCLS名前空間を作成します。 アプリケーションの存続期間全体にわたって。
- 次に、ミドルウェアを作成し、各リクエストに対して独自のCLSコンテキストを作成します。
- 新しいリクエストが到着すると、このミドルウェア(関数#1)が呼び出されます。
- この関数では、新しいCLSコンテキストを作成します(1つのオプションとして、 Namespace.runを使用できます)。 Namespace.runで、コンテキストのスコープで実行される関数を渡します。
- CLSは、 現在の実行IDキーを持つコンテキストを使用して、新しく作成されたコンテキストをマップに追加します。
- 各CLS名前空間には
active
プロパティがあります。 CLSはこのプロパティにコンテキストへの参照を割り当てます。 - コンテキストスコープでは、たとえばデータベースに対して何らかの非同期クエリを作成します。 コールバックをデータベースドライバーに渡します。これは、リクエストが完了すると呼び出されます。
- 非同期の初期化フックが起動します 。 現在のコンテキストを、非同期ID(新しい非同期操作のID)によるコンテキストとともにマップに追加します。
- なぜなら 関数には追加の命令はなく、実行を完了します。
- 非同期のafterフックが彼女のために起動します。
active
プロパティをundefined
名前空間に割り当てます(実際、常にではありません。複数のネストされたコンテキストを持つことができるためですが、最も単純な場合はそうです)。 - destroy非同期フックは、最初の非同期操作に対して起動します。 この操作の非同期IDによるコンテキストを持つマップからコンテキストを削除します(最初のコールバックの現在の実行IDと同じです)。
- データベース内のクエリが終了し、2番目のコールバックが呼び出されます。
- 前の非同期フック。 現在の実行IDは、2番目の操作(データベースクエリ)の非同期IDと同じです。 名前空間の
active
プロパティには、現在の実行IDによるコンテキストを含むマップで見つかったコンテキストが割り当てられます。 これは前に作成したコンテキストです。 - これで、2番目のコールバックが実行されます。 ある種のビジネスロジックが機能し、悪魔が踊り、ウォッカが注がれています。 この内部では、keyによってコンテキストから任意の値を取得できます 。 CLSは、現在のコンテキストで指定されたキーを検索するか、
undefined
返します。 - このコールバックの非同期afterフックは、完了するとトリガーされます。 名前空間の
active
プロパティをundefined
に設定active
ます。 - この操作に対して非同期非同期フックが起動します。 この操作の非同期IDによるコンテキストを持つマップからコンテキストを削除します(2番目のコールバックの現在の実行IDと同じです)。
- ガベージコレクター(GC)は、コンテキストオブジェクトに関連付けられているメモリを解放します。 このアプリケーションでは、これへのリンクはこれ以上ありません。
これは、ボンネットの下で何が起こっているかを簡略化したビューですが、主なフェーズとステップをカバーしています。 もっと深く掘り下げたいという希望がある場合は、 sortsに慣れることをお勧めします。 コードはわずか500行です。
トレースIDを作成する
ですから、CLSを扱った後、人類の利益のためにこのことを使おうとします。 ミドルウェアを作成してみましょう。リクエストごとに独自のCLSコンテキストを作成し、ランダムトレースIDを作成し、キーtraceID
を使用してコンテキストに追加します。 次に、コントローラーとサービスの内部で、このトレースIDを取得します。
エクスプレスでは、同様のミドルウェアは次のようになります。
const cls = require('cls-hooked') const uuidv4 = require('uuid/v4') const clsNamespace = cls.createNamespace('app') const clsMiddleware = (req, res, next) => { // req res - event emitters. CLS clsNamespace.bind(req) clsNamespace.bind(res) const traceID = uuidv4() clsNamespace.run(() => { clsNamespace.set('traceID', traceID) next() }) }
また、コントローラーまたはサービスでは、このtraceIDを1行のコードで取得できます。
const controller = (req, res, next) => { const traceID = clsNamespace.get('traceID') }
確かに、このトレースIDをログに追加しなくても、夏の除雪機のように、このトレースIDの恩恵を受けます。
トレースIDを自動的に追加する簡単なウィンストンフォーマッタを作成しましょう。
const { createLogger, format, transports } = require('winston') const addTraceId = printf((info) => { let message = info.message const traceID = clsNamespace.get('taceID') if (traceID) { message = `[TraceID: ${traceID}]: ${message}` } return message }) const logger = createLogger({ format: addTraceId, transports: [new transports.Console()], })
また、すべてのロガーが関数の形式でカスタムフォーマッターをサポートしている場合(多くの場合、これを行わない理由があります)、この記事はおそらくそうではなかったでしょう。 それでは、どのようにすてきなピノのログにトレースIDを追加できますか?
友人をロガーやCLSにするためにプロキシを呼び出します
プロキシ自体に関するいくつかの言葉:これは、元のオブジェクトをラップし、特定の状況でその動作を再定義できるようにするものです。 厳密に定義された限られた状況のリスト(科学ではtraps
と呼ばれます)。 ここで完全なリストを見つけることができます。トラップgetにのみ興味があります 。 オブジェクトのプロパティにアクセスするときに戻り値をオーバーライドする機会を与えます。 オブジェクトconst a = { prop: 1 }
をget
してProxyでラップすると、trap get
を使用して、 a.prop
にアクセスするときに好きなものをすべて返すことができます。
pino
の場合pino
アイデアは次のとおりです。リクエストごとにランダムなトレースIDを作成し、このトレースIDを渡すピノ子インスタンスを作成し、この子インスタンスをCLSに配置します。 次に、アクティブなコンテキストがあり、その中に子ロガーがある場合、この同じ子インスタンスをログに使用するプロキシでソースロガーをラップするか、元のロガーを使用します。
このような場合、プロキシは次のようになります。
const pino = require('pino') const logger = pino() const loggerCls = new Proxy(logger, { get(target, property, receiver) { // CLS , target = clsNamespace.get('loggerCls') || target return Reflect.get(target, property, receiver) }, })
ミドルウェアは次のようになります。
const cls = require('cls-hooked') const uuidv4 = require('uuid/v4') const clsMiddleware = (req, res, next) => { // req res - event emitters. CLS clsNamespace.bind(req) clsNamespace.bind(res) const traceID = uuidv4() const loggerWithTraceId = logger.child({ traceID }) clsNamespace.run(() => { clsNamespace.set('loggerCls', loggerWithTraceId) next() }) }
そして、次のようにロガーを使用できます。
const controller = (req, res, next) => { loggerCls.info('Long live rocknroll!') // // {"level":30,"time":1551385666046,"msg":"Long live rocknroll!","pid":25,"hostname":"eb6a6c70f5c4","traceID":"9ba393f0-ec8c-4396-8092-b7e4b6f375b5","v":1} }
cls-proxify
上記の考えに基づいて、 小さなcls-proxifyライブラリが作成されました。 彼女はエクスプレス 、 コア 、 ファストファイトですぐに動作します。 get
トラップを作成することに加えて、開発者により多くの自由を与える他のトラップを作成します。 このため、プロキシを使用して関数、クラスなどをラップできます。 pinoとfastify、pino、expressを統合する方法に関するライブデモがあります。
あなたが時間を無駄にしないことを願っています。そして、この記事は少なくともあなたにとって有用でした。 蹴って批判してください。 一緒にコードを改善する方法を学びます。