Log NodeJS dibuat benar

Apa yang paling mengganggu Anda saat berpikir tentang masuk ke NodeJS? Jika Anda bertanya kepada saya, saya akan mengatakan kurangnya standar industri untuk membuat ID jejak. Dalam artikel ini, kami akan mengulas bagaimana kami dapat membuat ID jejak ini (artinya kami akan memeriksa secara singkat bagaimana penyimpanan lokal yang berkelanjutan alias CLS bekerja) dan menggali lebih dalam tentang bagaimana kami dapat menggunakan Proxy untuk membuatnya bekerja dengan logger APA PUN.

Mengapa bahkan memiliki ID jejak untuk setiap permintaan di NodeJS?

Nah, pada platform yang menggunakan multi-threading dan menelurkan utas baru untuk setiap permintaan. Ada sesuatu yang disebut penyimpanan thread-local alias TLS , yang memungkinkan menjaga data sewenang-wenang tersedia untuk apa pun dalam utas. Jika Anda memiliki API asli untuk melakukannya, cukup sepele untuk membuat ID acak untuk setiap permintaan, masukkan ke TLS dan gunakan di controller atau layanan Anda nanti. Jadi apa masalahnya dengan NodeJS?
Seperti yang Anda ketahui, NodeJS adalah platform single-threaded (tidak terlalu benar lagi karena sekarang kami memiliki pekerja, tetapi itu tidak mengubah gambaran besar) platform, yang membuat TLS usang. Alih-alih mengoperasikan utas yang berbeda, NodeJS menjalankan panggilan balik yang berbeda dalam utas yang sama (ada serangkaian artikel hebat tentang perulangan acara di NodeJS jika Anda tertarik) dan NodeJS memberi kami cara untuk mengidentifikasi secara unik panggilan balik ini dan melacak hubungan mereka satu sama lain .

Kembali di masa lalu (v0.11.11) kami memiliki addAsyncListener yang memungkinkan kami untuk melacak peristiwa asinkron. Berdasarkan hal itu Forrest Norvell membangun implementasi pertama penyimpanan lokal lanjutan alias CLS . Kami tidak akan membahas implementasi CLS karena fakta bahwa kami, sebagai pengembang, telah kehilangan API tersebut di v0.12.

Sampai NodeJS 8 kami tidak memiliki cara resmi untuk terhubung ke pemrosesan acara async NodeJS. Dan akhirnya NodeJS 8 memberi kita kekuatan yang hilang melalui async_hooks (jika Anda ingin mendapatkan pemahaman yang lebih baik tentang async_hooks lihat artikel ini ). Ini membawa kita ke implementasi CLS berbasis async_hooks modern - cls-hooked .

Ikhtisar CLS

Berikut alur sederhana tentang cara kerja CLS:

Mari kita uraikan langkah demi langkah:

1. Katakanlah, kami memiliki server web yang khas. Pertama kita harus membuat namespace CLS. Sekali seumur hidup aplikasi kita.
2. Kedua, kita harus mengkonfigurasi middleware untuk membuat konteks CLS baru untuk setiap permintaan. Untuk kesederhanaan, mari kita asumsikan bahwa middleware ini hanyalah panggilan balik yang dipanggil saat menerima permintaan baru.
3. Jadi ketika permintaan baru tiba, kami memanggil fungsi panggilan balik itu.
4. Dalam fungsi itu kami membuat konteks CLS baru (salah satu caranya adalah menggunakan run API call).
5. Pada titik ini CLS menempatkan konteks baru dalam peta konteks dengan ID eksekusi saat ini .
6. Setiap namespace CLS memiliki properti active . Pada tahap ini CLS menetapkan active ke konteks.
7. Di dalam konteks kami membuat panggilan ke sumber daya tidak sinkron, katakanlah, kami meminta beberapa data dari database. Kami meneruskan panggilan balik ke panggilan itu, yang akan berjalan begitu permintaan ke database selesai.
8. init async hook diaktifkan untuk operasi asinkron baru. Itu menambahkan konteks saat ini ke peta konteks dengan ID async (menganggapnya sebagai pengidentifikasi operasi asinkron baru).
9. Karena kami tidak lagi memiliki logika di dalam callback pertama kami, ia keluar secara efektif mengakhiri operasi asinkron pertama kami.
10. setelah hook async dipecat untuk panggilan balik pertama. Ini menetapkan konteks aktif pada namespace menjadi undefined (itu tidak selalu benar karena kita mungkin memiliki beberapa konteks bersarang, tetapi untuk kasus yang paling sederhana itu benar).
11. menghancurkan kait dipecat untuk operasi pertama. Ini menghapus konteks dari peta konteks kami dengan ID async-nya (sama dengan ID eksekusi saat ini dari callback pertama kami).
12. Permintaan ke database telah selesai dan panggilan balik kedua kami akan dipicu.
13. Pada titik ini sebelum async hook berperan. ID eksekusi saat ini sama dengan ID async dari operasi kedua (permintaan basis data). Ini mengatur properti active namespace ke konteks yang ditemukan oleh ID eksekusi saat ini. Ini konteks yang kami buat sebelumnya.
14. Sekarang kita jalankan panggilan balik kedua. Jalankan beberapa logika bisnis di dalam. Dalam fungsi itu kita bisa mendapatkan nilai dengan kunci dari CLS dan itu akan mengembalikan apa pun yang ditemukan oleh kunci dalam konteks yang kita buat sebelumnya.
15. Dengan asumsi bahwa itu adalah akhir dari pemrosesan permintaan fungsi kami kembali.
16. setelah kait async dipecat untuk panggilan balik kedua. Ini mengatur konteks aktif pada namespace menjadi undefined .
17. destroy kait ditembakkan untuk operasi asinkron kedua. Itu menghapus konteks kita dari peta konteks dengan ID async-nya meninggalkannya benar-benar kosong.
18. Karena kami tidak lagi memegang referensi ke objek konteks, pemulung kami membebaskan memori yang terkait dengannya.

Ini adalah versi sederhana dari apa yang terjadi di bawah tenda, namun mencakup semua langkah utama. Jika Anda ingin menggali lebih dalam, Anda dapat melihat kode sumbernya . Itu kurang dari 500 baris.

Menghasilkan jejak ID

Jadi, begitu kita mendapatkan pemahaman keseluruhan tentang CLS, mari kita pikirkan bagaimana kita dapat menggunakannya untuk kebaikan kita sendiri. Satu hal yang bisa kami lakukan adalah membuat middleware yang membungkus setiap permintaan dalam suatu konteks, menghasilkan pengidentifikasi acak dan meletakkannya di CLS dengan key traceID . Kemudian, di dalam salah satu trilyun pengontrol dan layanan kami, kami bisa mendapatkan pengenal itu dari CLS.

Untuk mengekspresikan middleware ini bisa terlihat seperti ini:

 const cls = require('cls-hooked') const uuidv4 = require('uuid/v4') const clsNamespace = cls.createNamespace('app') const clsMiddleware = (req, res, next) => { // req and res are event emitters. We want to access CLS context inside of their event callbacks clsNamespace.bind(req) clsNamespace.bind(res) const traceID = uuidv4() clsNamespace.run(() => { clsNamespace.set('traceID', traceID) next() }) } 

Kemudian di controller kami, kami bisa mendapatkan jejak ID yang dihasilkan seperti ini:

 const controller = (req, res, next) => { const traceID = clsNamespace.get('traceID') } 

Tidak ada banyak penggunaan ID jejak ini kecuali kami menambahkannya ke log kami.

Mari tambahkan ke winston kami.

 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()], }) 

Nah, jika semua penebang mendukung formatters dalam bentuk fungsi (banyak dari mereka tidak melakukannya karena alasan yang baik) artikel ini tidak akan ada. Jadi bagaimana caranya menambahkan jejak jejak ke pino kesayanganku? Proksi untuk menyelamatkan!

Menggabungkan Proxy dan CLS

Proxy adalah objek yang membungkus objek asli kita sehingga memungkinkan kita untuk menimpa perilakunya dalam situasi tertentu. Daftar situasi ini (sebenarnya disebut jebakan) terbatas dan Anda dapat melihat seluruh rangkaian di sini , tetapi kami hanya tertarik pada jebakan perangkap. Ini memberi kami kemampuan untuk mencegat akses properti. Ini berarti bahwa jika kita memiliki objek const a = { prop: 1 } dan membungkusnya dalam Proxy, dengan get trap kita bisa mengembalikan apa pun yang kita inginkan untuk a.prop .

Jadi idenya adalah untuk menghasilkan ID jejak acak untuk setiap permintaan dan membuat logger pino anak dengan ID jejak dan memasukkannya ke dalam CLS. Kemudian kita bisa membungkus logger asli kita dengan Proxy, yang akan mengarahkan ulang semua permintaan logging ke logger anak di CLS jika ditemukan dan tetap menggunakan logger asli sebaliknya.

Dalam skenario ini Proksi kami dapat terlihat seperti ini:

 const pino = require('pino') const logger = pino() const loggerCls = new Proxy(logger, { get(target, property, receiver) { // Fallback to our original logger if there is no child logger in CLS target = clsNamespace.get('loggerCls') || target return Reflect.get(target, property, receiver) }, }) 

Middleware kami akan berubah menjadi seperti ini:

 const cls = require('cls-hooked') const uuidv4 = require('uuid/v4') const clsMiddleware = (req, res, next) => { // req and res are event emitters. We want to access CLS context inside of their event callbacks clsNamespace.bind(req) clsNamespace.bind(res) const traceID = uuidv4() const loggerWithTraceId = logger.child({ traceID }) clsNamespace.run(() => { clsNamespace.set('loggerCls', loggerWithTraceId) next() }) } 

Dan kita bisa menggunakan logger seperti ini:

 const controller = (req, res, next) => { loggerCls.info('Long live rocknroll!') // Logs something like // {"level":30,"time":1551385666046,"msg":"Long live rocknroll!","pid":25,"hostname":"eb6a6c70f5c4","traceID":"9ba393f0-ec8c-4396-8092-b7e4b6f375b5","v":1} } 

cls-proxify

Berdasarkan ide di atas, sebuah perpustakaan kecil bernama cls-proxify telah dibuat. Ini memiliki integrasi dengan express , koa dan fastify out-of-the-box.
Ini berlaku tidak hanya get jebakan ke objek asli, tetapi banyak lainnya juga. Jadi ada kemungkinan aplikasi yang tak terbatas. Anda dapat memanggil fungsi panggilan, konstruksi kelas, hampir apa saja! Anda hanya dibatasi oleh imajinasi Anda!
Lihatlah demo langsung menggunakannya dengan pino dan kencangkan, pino dan ekspres .

Semoga Anda menemukan sesuatu yang berguna untuk proyek Anda. Silakan sampaikan umpan balik Anda kepada saya! Saya sangat menghargai kritik dan pertanyaan apa pun.