Seringkali Anda perlu menulis informasi tambahan dalam log, yang dapat mengklarifikasi situasi dan lebih menyederhanakan proses debug aplikasi. Misalnya, jika informasi kesalahan dicatat, alangkah baiknya juga menyimpan data input dalam beberapa bentuk, sehingga lebih mudah untuk mereproduksi masalah. Di sini saya ingin menggambarkan suatu pendekatan yang memungkinkan Anda untuk mengumpulkan informasi tambahan ini.
Pernyataan masalah
Misalkan kita memiliki layanan ASP.NET MVC We. Ia menerima permintaan POST yang berisi deskripsi tentang apa yang perlu dilakukan dalam format JSON. Setelah menganalisis deskripsi seperti itu, layanan membuat dan mengeksekusi beberapa query SQL ke database. Dia kemudian menggabungkan hasilnya dan mengirimkannya ke klien.
Harus dikatakan bahwa layanan ini banyak menggunakan asynchrony dan multithreading melalui async / wait dan Task .
Sekarang kita mengerti apa yang kita hadapi, mari kita beralih ke masalah.
Terkadang layanan kami memberikan kesalahan. Alasannya bisa berbeda: input JSON salah, bug dalam kode, masalah dengan database ... Dalam hal ini, kita harus menulis informasi kesalahan ke log.
Tidak ada masalah masuk pengecualian itu sendiri. Kita bisa menangkapnya dalam metode aksi controller kita:
public class ServiceController : ApiController { [Route("api/service")] [HttpPost] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { try { ... } catch (Exception ex) { Logger.LogError(ex); throw; } } }
Atau kita dapat membuat atribut khusus untuk ini:
public class LogErrorAttribute : ActionFilterAttribute { public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext) { base.OnActionExecuted(actionExecutedContext); if (actionExecutedContext.Exception != null) { Logger.LogError(actionExecutedContext.Exception); } } }
dan menggunakannya pada metode tindakan:
[Route("api/service")] [HttpPost] [LogError] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { ... }
Tetapi kita membutuhkan lebih banyak. Untuk setiap kesalahan, kami ingin menyimpan informasi tambahan:
- Teks badan JSON dari permintaan.
- Teks dari semua kueri SQL yang dihasilkan.
Ada satu persyaratan lagi. Informasi tambahan ini harus dicatat dalam log hanya jika kesalahan terjadi. Kalau tidak, kita tidak membutuhkannya dalam log.
Melakukan ini untuk badan permintaan tidak sulit:
public class ServiceController : ApiController { [Route("api/service")] [HttpPost] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { var requestText = await Request.Content.ReadAsStringAsync(); try { ... } catch (Exception ex) { Logger.LogError(ex); Logger.LogError($"Request test is {requestText}"); throw; } } }
Tetapi untuk query SQL, semuanya tidak begitu sederhana. Faktanya adalah bahwa permintaan ini tidak dihasilkan oleh metode tindakan. Mereka bahkan tidak dihasilkan di controller. Antara metode tindakan dan metode yang menghasilkan SQL, ada banyak panggilan ke metode lain dari kelas lain. Bagaimana kita mengekstrak teks dari permintaan ini ketika kita membutuhkannya?
Salah satu opsi adalah menggunakan daftar pesan (mis. List<string> ). Kami membuatnya dalam metode tindakan kami ( ServiceAction ) dan meneruskannya ke metode yang menghasilkan SQL. Di sana kami akan menambahkan teks kueri SQL ke daftar ini. Jika terjadi kesalahan, metode tindakan akan memiliki daftar pesan yang perlu ditempatkan di log.
Metode ini memiliki kelemahan yang sangat signifikan, menurut saya,. Kita harus melewati daftar pesan di sepanjang rantai panggilan metode sampai kita mencapai metode yang menghasilkan SQL. Ini berarti bahwa di banyak tempat daftar pesan ini hanya diperlukan untuk meneruskannya. Ini menyulitkan kode, dan saya akan mencoba menghindarinya.
Jika Anda menggunakan wadah DI dan Anda dapat membuat kelas dari itu, maka Anda dapat mencoba untuk menempatkan daftar pesan dalam wadah dengan masa hidup "per permintaan". Kelas generasi SQL akan menerima daftar pesan ini sebagai parameter konstruktor. Kemudian instance dari kelas ini dan instance dari controller akan dapat mengakses instance yang sama dari daftar pesan.
Tetapi ada cara yang lebih mudah untuk mengumpulkan informasi kontekstual bahkan jika Anda tidak menggunakan wadah DI. Alangkah baiknya jika kita dapat mengakses daftar pesan melalui properti statis:
public static async Task<SqlDataReader> RunReaderAsync(this SqlCommand cmd) { var message = $"SQL Server query is: {cmd.CommandText}"; ErrorContext.Current.AttachMessage(message); ... }
Ada masalah serius di sini. Layanan kami secara bersamaan dapat melayani beberapa permintaan. Dan setiap permintaan tersebut harus memiliki daftar pesannya sendiri. Selain itu, ketika memproses satu permintaan, kode kami dapat menelurkan beberapa utas (misalnya, menggunakan async / menunggu ). Dan semua utas ini harus memiliki akses ke daftar pesan yang sama. Bagaimana ini bisa diterapkan?
Kelas AsyncLocal<T> membantu kami. Ini menjamin bahwa jika Anda meletakkan beberapa nilai pada instance kelas ini di satu utas, maka Anda bisa mendapatkan nilai ini di utas ini, serta di semua utas yang diluncurkan dari yang ini mulai sekarang. Pada saat yang sama, semua utas lainnya tidak akan memiliki akses ke nilai ini.
Mari kita lihat implementasi kelas ErrorContext :
public class ErrorContext { private static readonly object Lock = new object(); private static readonly AsyncLocal<ErrorContext> CurrentErrorContext = new AsyncLocal<ErrorContext>(); private readonly Lazy<ConcurrentBag<string>> _attachedMessages = new Lazy<ConcurrentBag<string>>(() => new ConcurrentBag<string>()); private ErrorContext() {} public static ErrorContext Current { get { lock (Lock) { var errorContext = CurrentErrorContext.Value; if (errorContext == null) { CurrentErrorContext.Value = errorContext = new ErrorContext(); } return errorContext; } } } public static ErrorContext CreateNewErrorContext() { lock (Lock) { var errorContext = new ErrorContext(); CurrentErrorContext.Value = errorContext; return errorContext; } } public void AttachMessage(string message) { if (!string.IsNullOrWhiteSpace(message)) { _attachedMessages.Value.Add(message); } } public IReadOnlyList<string> GetMessages() { return _attachedMessages.Value.ToArray(); } }
Metode CreateNewErrorContext segera membuat daftar pesan baru dan menyimpannya di bidang CurrentErrorContext , yang merupakan tipe AsyncLocal . Anda dapat mengakses daftar saat ini di mana saja dalam kode menggunakan properti statis Current . Metode AttachMessage menambahkan pesan baru ke daftar. Ini menyimpan pesan dalam contoh ConcurrentBag , karena metode ini dapat dipanggil dari beberapa utas pada saat yang sama. Metode GetMessages mengembalikan semua pesan yang disimpan, sehingga mereka dapat ditulis ke log.
Sekarang Anda dapat dengan mudah menginisialisasi dan menggunakan ErrorContext di dalam LogErrorAttribute :
public class LogErrorAttribute : ActionFilterAttribute { public override void OnActionExecuting(HttpActionContext actionContext) { ErrorContext.CreateNewErrorContext(); base.OnActionExecuting(actionContext); } public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext) { base.OnActionExecuted(actionExecutedContext); if (actionExecutedContext.Exception != null) { foreach(var message in ErrorContext.Current.GetMessages()) { Logger.LogError(message); } Logger.LogError(actionExecutedContext.Exception); } } }
Di mana saja dalam kode Anda, Anda dapat menambahkan pesan Anda ke konteks kesalahan saat ini sebagai berikut:
ErrorContext.Current.AttachMessage(message);
Pencatatan Kinerja
Terkadang layanan saya lambat. Tidak untuk semua pertanyaan, tetapi untuk beberapa pertanyaan, terlalu lama untuk diselesaikan. Saya ingin menyimpan informasi tentang permintaan tersebut untuk menganalisisnya nanti. Bagaimana ini bisa diterapkan, dan informasi apa yang kita butuhkan?
Pertama-tama, saya perlu ambang runtime. Jika memproses permintaan membutuhkan waktu lebih sedikit, maka semuanya beres. Saya tidak akan menulis apa pun ke log dalam kasus ini. Tetapi jika itu membutuhkan lebih banyak waktu, saya harus menambahkan beberapa informasi ke log.
Informasi apa yang saya butuhkan? Anda pasti perlu tahu berapa lama pemrosesan permintaan. Tetapi itu tidak cukup. Layanan saya melakukan banyak hal: memeriksa parameter kueri, mendapatkan data dari layanan lain, membuat kueri SQL, dan mengeksekusinya ... Saya perlu tahu berapa banyak waktu yang dibutuhkan setiap bagian untuk memahami di mana masalahnya disembunyikan.
Selain itu, saya memerlukan informasi yang sama dengan kesalahan. Saya membutuhkan badan permintaan untuk dapat mereproduksi masalah. Saya membutuhkan teks-teks dari query SQL jika mereka membutuhkan waktu paling lama.
Bagaimana ini bisa dicapai? Sekali lagi, menggunakan kelas AsyncLocal :
public class Timer : IDisposable { private static readonly object Lock = new object(); private static readonly AsyncLocal<Timer> CurrentTimer = new AsyncLocal<Timer>(); private readonly Stopwatch _stopwatch = new Stopwatch(); private readonly Lazy<ConcurrentQueue<Timer>> _attachedTimers = new Lazy<ConcurrentQueue<Timer>>(() => new ConcurrentQueue<Timer>()); private readonly Lazy<ConcurrentQueue<string>> _attachedMessages = new Lazy<ConcurrentQueue<string>>(() => new ConcurrentQueue<string>()); private readonly string _description; private readonly TimeSpan? _threshold; private readonly Timer _previousCurrent; private bool _isDisposed; private bool _suspendLogging; private Timer(Timer previousCurrent, string description = null, TimeSpan? threshold = null) { _previousCurrent = previousCurrent; _description = description; _threshold = threshold; _stopwatch.Start(); } public static Timer Current { get { lock (Lock) { var timer = CurrentTimer.Value; if (timer == null) { CurrentTimer.Value = timer = new Timer(null); } return timer; } } } public static Timer SetCurrentTimer(string description, TimeSpan? threshold = null) { lock (Lock) { var currentTimer = CurrentTimer.Value; var timer = new Timer(currentTimer, description, threshold); CurrentTimer.Value = timer; currentTimer?._attachedTimers.Value.Enqueue(timer); return timer; } } public void AttachMessage(string message) { if (!string.IsNullOrWhiteSpace(message)) { _attachedMessages.Value.Enqueue(message); } } public void Dispose() { if (!_isDisposed) { _isDisposed = true; _stopwatch.Stop(); if (_attachedTimers.IsValueCreated) { foreach (var attachedTimer in _attachedTimers.Value) { attachedTimer.Dispose(); } } if (!_suspendLogging && _threshold.HasValue && _stopwatch.Elapsed > _threshold.Value) { Log(); } if (_previousCurrent != null) { CurrentTimer.Value = _previousCurrent; } } } private JObject Message { get { Dispose(); var message = new StringBuilder($"It took {_stopwatch.ElapsedMilliseconds} ms to execute {_description}."); if (_threshold.HasValue) { message.Append($" Duration threshold is {_threshold.Value.TotalMilliseconds} ms."); } var messageObj = new JObject { ["message"] = message.ToString(), }; if (_attachedTimers.IsValueCreated && _attachedTimers.Value.Any()) { messageObj["attachedTimers"] = new JArray(_attachedTimers.Value.Select(t => t.Message)); } if (_attachedMessages.IsValueCreated && _attachedMessages.Value.Any()) { messageObj["attachedMessages"] = new JArray(_attachedMessages.Value); } return messageObj; } } public void Log() { try { _suspendLogging = true; Dispose(); if (_stopwatch.Elapsed < _threshold) { Logger.LogDebug(Message.ToString()); } else { Logger.LogWarning(Message.ToString()); } } finally { _suspendLogging = false; } } }
Mari kita lihat cara kerjanya. Metode SetCurrentTimer membuat timer baru. Di sini Anda dapat menentukan deskripsinya dan ambang batas waktu opsional.
Mengapa ambang batas ini opsional? Kadang-kadang saya perlu bagian dari kode saya untuk menjalankan tidak lebih dari jumlah waktu tertentu. Jadi saya dapat berharap bahwa seluruh permintaan layanan diproses dalam 3 detik. Dalam kasus lain, saya tidak ingin memaksakan pembatasan pada runtime. Misalnya, tidak masalah bagi saya berapa lama waktu yang diperlukan untuk menjalankan kueri SQL hingga seluruh permintaan layanan diproses dalam waktu kurang dari 3 detik. Untuk alasan ini, untuk beberapa timer, ambang batas waktu perlu diatur, sedangkan untuk yang lain tidak.
Di dalam metode SetCurrentTimer , timer baru dibuat dan dimasukkan ke dalam variabel CurrentTimer tipe AsyncLocal . Tapi itu belum semuanya. Pada titik ini, timer aktif lain mungkin sudah ada. Dalam hal ini, timer baru yang baru saja Anda buat bergabung dengan yang sudah ada. Ini memungkinkan Anda untuk membuat penghitung waktu bersarang untuk mengukur waktu eksekusi dari seluruh blok kode dan bagian-bagiannya:
using (Timer.SetCurrentTimer("The whole block")) { ... using (Timer.SetCurrentTimer("Part 1")) { ... } ... using (Timer.SetCurrentTimer("Part 2")) { ... } ... }
Properti Current ini memberikan akses ke timer saat ini. Ini berguna jika Anda ingin menambahkan beberapa pesan ke dalamnya:
var message = $"SQL Server query is: {cmd.CommandText}"; Timer.Current.AttachMessage(message);
Di sini, pesan terlampir dan penghitung waktu bersarang disimpan dalam instance ConcurrentQueue , karena urutannya mungkin penting.
Properti Message mengembalikan pesan yang dikumpulkan dalam satu unit dari arus dan semua timer ditumpuk di dalamnya. Di sini saya menggunakan kelas JSON dari pustaka JSON.NET untuk menyusun semua pesan. Tetapi sebenarnya itu tidak begitu penting. Anda dapat menggunakan format apa pun.
Metode Log menulis informasi yang disimpan dalam timer ke log, terlepas dari apakah ambang waktu berjalan telah ditetapkan atau tidak. Pada saat yang sama, metode Dispose menulis informasi ke log hanya jika ambang batas runtime yang ditetapkan telah terlampaui.
Sekarang kita dapat membuat atribut lain untuk metode pengontrol kami:
public class TimerContextAttribute : ActionFilterAttribute { private readonly string _timerDescription; private readonly int _durationThresholdMs; private readonly AsyncLocal<Timer> _timer = new AsyncLocal<Timer>(); public TimerContextAttribute(string timerDescription, int durationThresholdMs) { if (string.IsNullOrWhiteSpace(timerDescription)) throw new ArgumentNullException(nameof(timerDescription)); _timerDescription = timerDescription; _durationThresholdMs = durationThresholdMs; } public override void OnActionExecuting(HttpActionContext actionContext) { _timer.Value = Timer.SetCurrentTimer(_timerDescription, TimeSpan.FromMilliseconds(_durationThresholdMs)); base.OnActionExecuting(actionContext); } public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext) { base.OnActionExecuted(actionExecutedContext); _timer.Value?.Dispose(); } }
dan menggunakannya pada metode tindakan seperti ini:
[Route("api/service")] [HttpPost] [TimerContext("For ServiceAction method", 3000)] public async Task<HttpResponseMessage> ServiceAction( [FromBody] RequestModel requestModel ) { ... }
Kesimpulan
Dalam artikel ini, saya menjelaskan betapa sederhananya mengumpulkan informasi dari banyak tempat dalam kode dan mengaksesnya nanti. Fungsionalitas tersebut dapat diimplementasikan menggunakan properti dan metode statis yang memanipulasi instance dari kelas AsyncLocal .
Saya harap artikel ini akan bermanfaat untuk meningkatkan sistem logging di aplikasi Anda.