Saat membaca
Radar Teknologi ThoughtWorks , saya menemukan teknik "
Permintaan Logging Terpisah ". Kami di
Confirmit menggunakan logging secara ekstensif, dan saya bertanya-tanya bagaimana fungsi ini dapat diimplementasikan.
Deskripsi masalah
Mari kita lihat apa yang dipertaruhkan. Misalkan kita memiliki layanan web. Pada titik tertentu, itu mulai mogok di server produksi, tetapi hanya untuk beberapa permintaan. Misalnya, kerusakan hanya terjadi untuk pengguna tertentu. Atau hanya pada titik akses terpisah ... Kita perlu menemukan alasannya. Dalam hal ini, penebangan akan membantu kami.
Kami dapat memasukkan cukup instruksi pendataan ke dalam kode kami untuk memahami penyebab masalahnya. Instruksi ini biasanya mencocokkan pesan Anda dengan level log tertentu (Debug, Info, Peringatan, ...). Selain itu, log itu sendiri juga memiliki level sendiri. Semua pesan dengan level di atas level log akan direkam dalam penyimpanan log (file, database, ...). Jika level pesan lebih rendah dari level log, pesan akan dibuang begitu saja.
Ketika aplikasi kita berfungsi dengan baik, kita ingin melihat entri log sesedikit mungkin sehingga ukurannya tetap kecil. Pada saat yang sama, jika aplikasi macet, kami ingin log memiliki entri yang cukup sehingga kami dapat memahami penyebab masalah. Kesulitannya di sini adalah bahwa kita biasanya mengatur satu level logging untuk semua penebang di aplikasi kita. Jika semuanya beres, kami menjaga level ini tinggi (misalnya, Peringatan). Jika kita perlu mencari penyebab kegagalannya, kita menginstalnya di bawah ini (misalnya, Debug).
Satu tingkat pencatatan per aplikasi
Ketika kami mengatur level logging di aplikasi rendah, log store kami dipenuhi dengan banyak pesan. Pesan-pesan ini datang dari permintaan yang berbeda dan dicampur di antara mereka sendiri, karena permintaan dapat dilayani secara bersamaan. Ini mengarah ke sejumlah masalah potensial:
- Bagaimana cara memisahkan pesan permintaan yang bermasalah dari pesan permintaan lainnya?
- Permintaan yang tidak menyebabkan kerusakan masih menghabiskan waktu menulis ke repositori log, meskipun pesan-pesan ini tidak akan pernah digunakan.
- Pesan dari permintaan yang berhasil akan memakan ruang di repositori log, meskipun pesan ini tidak akan pernah digunakan.
Jujur, kesulitan-kesulitan ini tidak dapat diatasi. Untuk memisahkan pesan permintaan "baik" dari pesan permintaan "buruk", Anda dapat menggunakan
id korelasi . Semua sistem pemrosesan log modern memungkinkan penyaringan catatan dengan berbagai kriteria, termasuk ini.
Kinerja juga biasanya bukan masalah utama. Sistem logging mendukung perekaman asinkron, sehingga efek dari logging besar-besaran umumnya tidak mengganggu.
Dan ruang disk sekarang relatif murah, jadi menyimpan banyak catatan bukanlah masalah. Terutama jika kita dapat menghapus catatan lama dari waktu ke waktu.
Namun, dapatkah kita memperbaiki sistem ini? Bisakah kita menetapkan level logging terpisah untuk setiap permintaan, tergantung pada kondisi tertentu? Saya ingin mempertimbangkan masalah ini di sini.
Pisahkan level logging untuk setiap permintaan
Biarkan saya menyatakan persyaratan untuk solusi yang akan saya terapkan. Harus ada cara untuk menetapkan tingkat logging yang terpisah untuk setiap permintaan. Harus ada cara yang fleksibel untuk menentukan kondisi yang menentukan pilihan level ini untuk permintaan tertentu. Dan harus dimungkinkan untuk mengubah kondisi ini selama eksekusi program tanpa perlu me-restart itu.
Jadi, tugas sudah diatur. Mari kita mulai.
Saya akan membuat layanan web sederhana berdasarkan .NET Core. Ia akan memiliki satu pengontrol:
[Route("api/[controller]")] [ApiController] public class ValuesController : ControllerBase { ...
Kami akan membahas implementasi properti
Logger nanti. Untuk aplikasi ini saya akan menggunakan library
log4net untuk logging. Perpustakaan ini memberikan peluang yang menarik. Saya berbicara tentang
tingkat warisan . Singkatnya, jika dalam konfigurasi pustaka ini, Anda mengatakan bahwa log dengan nama
X harus memiliki tingkat
Info logging, ini berarti bahwa semua log dengan nama dimulai dengan
X. (misalnya,
XY ,
XZ ,
XAB ) akan mewarisi level yang sama ini.
Dari sinilah muncul ide orisinal. Untuk setiap permintaan, entah bagaimana saya akan menentukan tingkat pencatatan yang diperlukan. Kemudian saya akan membuat log bernama baru di konfigurasi
log4net . Log ini akan memiliki level logging yang diperlukan. Setelah itu, semua objek logger yang dibuat sebagai bagian dari permintaan saat ini harus memiliki nama yang dimulai dengan nama log baru ini yang dibuat oleh saya. Satu-satunya masalah di sini adalah
log4net tidak pernah menghapus log. Setelah dibuat, mereka ada sepanjang masa aplikasi. Karena alasan ini, saya awalnya membuat satu log untuk setiap tingkat logging yang memungkinkan:
<?xml version="1.0" encoding="utf-8" ?> <log4net> <appender name="Console" type="log4net.Appender.ConsoleAppender"> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%5level [%thread] (%file:%line) - %message%newline" /> </layout> </appender> <appender name="RollingFile" type="log4net.Appender.RollingFileAppender"> <file value="RequestLoggingLog.log" /> <appendToFile value="true" /> <maximumFileSize value="100KB" /> <maxSizeRollBackups value="2" /> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%level %thread %logger - %message%newline" /> </layout> </appender> <root> <level value="WARN" /> <appender-ref ref="Console" /> <appender-ref ref="RollingFile" /> </root> <logger name="EdlinSoftware.Log.Error"> <level value="ERROR" /> </logger> <logger name="EdlinSoftware.Log.Warning"> <level value="WARN" /> </logger> <logger name="EdlinSoftware.Log.Info"> <level value="INFO" /> </logger> <logger name="EdlinSoftware.Log.Debug"> <level value="DEBUG" /> </logger> </log4net>
Sekarang saya punya beberapa log dengan nama
EdlinSoftware.Log.XXXX . Nama-nama ini akan berfungsi sebagai awalan nama-nama log yang digunakan dalam kueri. Untuk menghindari tabrakan di antara permintaan, saya akan menyimpan awalan yang dihitung untuk permintaan ini dalam instance
AsyncLocal . Nilai objek ini akan ditetapkan dalam middleware OWIN baru:
app.Use(async (context, next) => { try { LogSupport.LogNamePrefix.Value = await LogSupport.GetLogNamePrefix(context); await next(); } finally { LogSupport.LogNamePrefix.Value = null; } });
Ketika nilai ini disetel, sangat mudah untuk membuat logger dengan awalan nama yang diinginkan:
public static class LogSupport { public static readonly AsyncLocal<string> LogNamePrefix = new AsyncLocal<string>(); public static ILog GetLogger(string name) { return GetLoggerWithPrefixedName(name); } public static ILog GetLogger(Type type) { return GetLoggerWithPrefixedName(type.FullName); } private static ILog GetLoggerWithPrefixedName(string name) { if (!string.IsNullOrWhiteSpace(LogNamePrefix.Value)) { name = $"{LogNamePrefix.Value}.{name}"; } return LogManager.GetLogger(typeof(LogSupport).Assembly, name); } .... }
Sekarang sudah jelas bagaimana cara mendapatkan instance logger di controller kami:
[Route("api/[controller]")] [ApiController] public class ValuesController : ControllerBase { private ILog _logger; private ILog Logger { get => _logger ?? (_logger = LogSupport.GetLogger(typeof(ValuesController))); } .... }
Tetap hanya melakukan satu hal: entah bagaimana mengatur aturan yang dengannya kami memilih tingkat logging untuk setiap permintaan. Ini harus menjadi mekanisme yang cukup fleksibel. Ide dasarnya adalah menggunakan skrip C #. Saya akan membuat file
LogLevelRules.json , di mana saya akan mendefinisikan satu set pasangan "aturan - tingkat logging":
[ { "logLevel": "Debug", "ruleCode": "context.Request.Path.Value == \"/api/values/1\"" }, { "logLevel": "Debug", "ruleCode": "context.Request.Path.Value == \"/api/values/3\"" } ]
Di sini
logLevel adalah level logging yang diinginkan, dan
ruleCode adalah kode C # yang mengembalikan nilai Boolean untuk permintaan yang diberikan. Aplikasi akan menjalankan kode aturan satu per satu. Aturan pertama, yang kodenya kembali benar, akan digunakan untuk mengatur tingkat pencatatan yang sesuai. Jika semua aturan mengembalikan false, tingkat standar akan digunakan.
Untuk membuat delegasi dari representasi string aturan, kelas
CSharpScript digunakan :
public class Globals { public HttpContext context; } internal class LogLevelRulesCompiler { public IReadOnlyList<LogLevelRule> Compile(IReadOnlyList<LogLevelRuleDescription> levelRuleDescriptions) { var result = new List<LogLevelRule>(); foreach (var levelRuleDescription in levelRuleDescriptions ?? new LogLevelRuleDescription[0]) { var script = CSharpScript.Create<bool>(levelRuleDescription.RuleCode, globalsType: typeof(Globals)); ScriptRunner<bool> runner = script.CreateDelegate(); result.Add(new LogLevelRule(levelRuleDescription.LogLevel, runner)); } return result; } } internal sealed class LogLevelRule { public string LogLevel { get; } public ScriptRunner<bool> Rule { get; } public LogLevelRule(string logLevel, ScriptRunner<bool> rule) { LogLevel = logLevel ?? throw new ArgumentNullException(nameof(logLevel)); Rule = rule ?? throw new ArgumentNullException(nameof(rule)); } }
Di sini, metode
Kompilasi mengambil daftar objek yang dibaca dari file
LogLevelRules.json . Ini menciptakan delegasi
pelari untuk setiap aturan.
Daftar delegasi ini dapat disimpan:
LogSupport.LogLevelSetters = new LogLevelRulesCompiler().Compile( new LogLevelRulesFileReader().ReadFile("LogLevelRules.json") );
dan digunakan di masa depan:
public static class LogSupport { internal static IReadOnlyList<LogLevelRule> LogLevelSetters = new LogLevelRule[0]; ... public static async Task<string> GetLogNamePrefix(HttpContext context) { var globals = new Globals { context = context }; string result = null; foreach (var logLevelSetter in LogLevelSetters) { if (await logLevelSetter.Rule(globals)) { result = $"EdlinSoftware.Log.{logLevelSetter.LogLevel}"; break; } } return result; } }
Jadi, ketika aplikasi dimulai, kita membaca
LogLevelRules.json , konversikan isinya ke daftar delegasi menggunakan kelas
CSharpScript , dan simpan daftar ini di bidang
LogSupport.LogLevelSetters . Kemudian, untuk setiap permintaan, kami menjalankan delegasi dari daftar ini untuk mendapatkan level logging.
Satu-satunya yang tersisa untuk dilakukan adalah melacak perubahan pada file
LogLevelRules.json . Jika kami ingin mengatur level logging untuk beberapa permintaan, kami menambahkan aturan baru ke file ini. Untuk memaksa aplikasi kita menerapkan perubahan ini tanpa memulai ulang, perlu untuk memantau file:
var watcher = new FileSystemWatcher { Path = Directory.GetCurrentDirectory(), Filter = "*.json", NotifyFilter = NotifyFilters.LastWrite }; watcher.Changed += (sender, eventArgs) => {
Perlu dicatat bahwa demi singkatnya, saya menghilangkan kode sinkronisasi aliran ketika bekerja dengan bidang
LogSupport.LogLevelSetters . Namun dalam praktiknya, sinkronisasi seperti itu diperlukan.
Kode aplikasi lengkap dapat ditemukan di
GitHub .
Kekurangan
Kode yang ditunjukkan di atas memungkinkan Anda untuk memecahkan masalah pengaturan level logging terpisah untuk setiap permintaan. Namun dia memiliki sejumlah kekurangan. Mari kita bahas mereka.
1. Pendekatan ini mengubah nama log. Jadi, alih-alih "
MyClassLogger ", sesuatu seperti "
Edlinsoft.Log.Debug.MyClassLogger " akan disimpan dalam repositori log. Anda dapat hidup dengan itu, tetapi itu tidak terlalu nyaman. Mungkin masalah dapat diatasi dengan mengubah tata letak log (tata letak log).
2. Sekarang tidak mungkin untuk menggunakan instance statis dari kelas logger, karena mereka harus dibuat secara terpisah untuk setiap permintaan. Masalah yang paling serius di sini, menurut saya, adalah bahwa pengembang harus selalu mengingat hal ini. Seseorang mungkin secara tidak sengaja membuat bidang statis dengan pencatat dan mendapatkan hasil yang aneh. Anda dapat mengatasi situasi ini dengan membuat kelas wrapper untuk logger daripada menggunakan kelas
log4net secara langsung. Wrapper seperti itu selalu dapat membuat instance baru dari
log4net logger untuk setiap operasi. Dalam hal ini, dapat digunakan secara bebas di bidang statis.
3. Pendekatan yang diuraikan menciptakan banyak contoh penebang. Ini menghabiskan memori dan siklus prosesor selama pembuatan dan selama pengumpulan sampah. Tergantung pada aplikasi Anda, ini mungkin atau mungkin bukan masalah yang signifikan.
4. Ketika kita mengubah file JSON dengan aturan, kode aturan mungkin mengandung kesalahan. Sangat mudah untuk menggunakan blok try-catch sehingga kesalahan ini tidak merusak aplikasi utama kami. Namun, entah bagaimana kita perlu mengetahui bahwa ada yang tidak beres. Ada dua jenis kesalahan:
- Kesalahan waktu kompilasi untuk kode aturan dalam delegasi.
- Kesalahan runtime dari delegasi ini.
Entah bagaimana kita perlu mencari tahu tentang kesalahan ini, kalau tidak, logging kita tidak akan berfungsi, dan kita bahkan tidak akan mengetahuinya.
5. Kode aturan dalam file JSON pada prinsipnya dapat berisi instruksi apa pun. Ini berpotensi menyebabkan masalah keamanan. Penting untuk membatasi kemampuan kode ini. Di sisi lain, jika penyerang dapat langsung menulis ke file aplikasi Anda, maka masalah keamanan sudah jelas.
Kesimpulan
Secara umum, saya tidak mendapatkan kesan bahwa solusi seperti itu harus menggantikan pendekatan yang ada untuk logging. Alat yang bagus dengan kemampuan untuk memfilter entri log dapat membantu di sini bahkan ketika menggunakan satu tingkat logging untuk seluruh aplikasi. Namun demikian, saya berharap bahwa analisis masalah ini akan memberi Anda makanan untuk dipikirkan.