Di tulisan ini saya ingin membahas mengenai kenapa kita butuh logging dalam aplikasi, dan bagaimana praktik terbaik untuk melakukan logging.
Daftar Isi
Kenapa butuh logging
Kita memerlukan log supaya tahu apa kesalahan yang mungkin terjadi ketika program berjalan. Meskipun program dirancang sempurna, tetap ada banyak hal kemungkinan error yang bisa terjadi ketika aplikasi berjalan. Error ini bisa karena banyak hal, tapi bisa dibagi menjadi dua yang utama:
- karena masalah pada runtime environment (lingkungan eksekusi program), misalnya: disk space habis, jaringan putus, disk error, dsb
- karena logika program yang salah, atau ada library yang memiliki bug tertentu
Sering kali kita tidak bisa mengakses sistem di mana software kita berjalan, jadi tidak bisa langsung menginspeksi masalahnya apa. Contoh kasusnya:
- Pada aplikasi desktop/game yang berjalan di komputer client
- Pada aplikasi server yang berjalan di sistem production
Log level
Mencatat semua aktivitas program di log akan membuang banyak CPU dan disk space. Jadi kita perlu memberi tag level ketika melakukan logging.
Sistem log yang baik dapat diset agar hanya log pada level tertentu yang disimpan atau ditampilkan. Tergantung kebutuhan, level log bisa diset saat aplikasi berjalan (runtime) jika ada masalah.
Log level: ERROR dan WARNING
Beberapa hal yang pasti perlu dilog adalah:
- Error pada program
- Hal-hal abnormal yang perlu diperhatikan (warning)
Sedangkan kasus selain itu sangat tergantung pada aplikasi. Dua level untuk kedua kasus itu sesuai namanya: ERROR dan WARNING.
Untuk kasus error, sudah jelas: segala macam exception dari sistem dan library perlu dilog (disk space habis, disk error, dsb). Sedangkan yang dimaksud dengan warning adalah: hal-hal abnormal yang mungkin jadi masalah, tapi program masih bisa terus berjalan untuk saat ini. Contoh warning: disk space hampir habis, proses database butuh waktu lebih dari normal.
Log Level: INFO
Program kadang perlu melakukan sesuatu yang tidak terlalu penting untuk disimpan di database tapi perlu untuk debugging. Contoh: jika program secara otomatis akan melakukan koneksi ke server random pada saat startup, maka program sebaiknya menuliskan di log file server mana yang saat itu dipilih. Ketika suatu saat ada error, bisa jelas server mana yang perlu dicek. Hal-hal seperti ini masuk dalam log level INFO.
Log Level: DEBUG
Kadang sebuah bug hanya ditemukan dengan menjalankan program. Hal ini bisa terjadi misalnya karena bug tertentu hanya muncul jika load CPU sangat tinggi, atau ada dua thread yang memiliki race condition, dan hal ini sulit ditemukan bahkan dengan test case yang lengkap.
Dalam kasus seperti ini, kita kadang perlu menuliskan log yang sangat detail, misalnya “Entering function x, with parameter 123”. Log ini kadang perlu sangat detail jika memang dicurigai ada fungsi tertentu di thread lain yang mengubah variabel tertentu.
Kasus lain adalah: mungkin kita tidak yakin dengan behavior sebuah library dalam menangani input tertentu. Contoh input yang kadang menjadi masalah adalah format JSON. Standard JSON kurang jelas dalam kasus key duplikat, dalam kasus seperti ini:
{“a”:2, “a”:3}
Nilai apa yang akan diambil oleh library JSON? biasanya terakhir, tapi tergantung library dan sistem yang dipakai (contohnya di MySQL: nilai pertama yang dipakai). Ini tidak jadi masalah jika semua data diproses di sistem kita sendiri, tapi jadi masalah jika kita mengirimkan data ke sistem lain juga, misalnya:
- Program menerima JSON dengan key ID yang duplikat, mengekstrak ID (dari nilai pertama)
- Program mengirimkan JSON ke web service lain apa adanya, dan webservice mengambil nilai ID terakhir
Sebagai catatan: di hampir semua library JSON, pengguna library bahkan tidak bisa mendeteksi apakah ada key duplikat atau tidak. Jadi dalam kasus tertentu, nilai JSON perlu dilog sebagai teks apa adanya di level DEBUG.
Log Level: TRACE
Ketika development, kadang kita ingin melakukan logging ekstra untuk mencari bug tertentu. Setelah bugnya ketemu, kita bisa menghapus log trace ini. Sebaiknya log trace ini tidak sampai dipush ke repository. Jadi log level ini sekedar pengingat bahwa nanti akan perlu dihapus lagi.
Konteks dalam pesan error
Pesan log harus memiliki informasi yang cukup jelas untuk mencari tahu kasus errornya. Pesan yang jelek misalnya: “Exception occured” (exception apa? di mana? kenapa?). Sedangkan yang lebih baik misalnya: “RecordNotFoundException for userid: 1234”.
Structured Logging
Sebuah log bisa berupa baris teks biasa, tapi ini akan sulit diproses komputer. Sebagian log memakai format binary, tapi akan sulit dicek manusia. Biasanya jalan tengah yang diambil adalah log dalam format teks terstruktur, misalnya dalam format JSON dengan key yang disepakati.
Contoh logging dengan struktur adalah seperti ini:
Saat ini ada beberapa logging library yang mendukung structured logging ,misalnya: log15 untuk Go, structlog untuk Python, dsb.
Perlu diperhatikan juga ketika memakai sistem logging third party bahwa ada key tertentu yang memiliki makna khusus. Contohnya: datadog memiliki beberapa key khusus.
Security dan Log Scrubbing
Untuk alasan security, kita jangan melakukan logging informasi sensitif. Contohnya: password, kartu kredit, dsb. Jadi jangan sampai ada log: “Login failed for user ‘admin’ with passsword ‘1234’”.
Dalam kondisi tertentu, informasi tetap tidak sengaja terlog (misalnya dalam kasus logging data JSON). Di sini log scrubbing perlu dilakukan. Berbagai sistem memiliki fitur ini built in (contohnya, berikut ini rule dari Datadog).
Perlu diperhatikan bahwa log scrubbing pada data log yang unstructured (sekedar teks mentah) hanya bisa dilakukan dengan pattern matching. Artinya:
- jika pattern kurang lengkap, akan ada data yang bocor
- jika pattern terlalu generik, maka informasi penting dalam error message (misalnya Request ID) yang terlog juga bisa disensor
Log dan Performance
Logging dalam menimbulkan masalah performance, misalnya baris sederhana ini:
log.debug("User count is", countUsers());Dalam banyak bahasa yang terjadi adalah: countUsers() dipanggil, lalu log.debug dipanggil dengan parameter jumlah user. Di dalam log.debug, dicek bahwa ternyata saat ini level logging adalah warning, jadi tidak perlu menuliskan log ke file, tapi fungsi countUsers() sudah terlanjur dipanggil.
Jika countUsers() ternyata mengakses database untuk menentukan jumlah user, maka ada banyak akses database yang tidak diperlukan. Contoh lain yang berbahaya adalah logging di dalam loop seperti ini:
for (let user in users) {
logger.debug("User info ", user.toString());
}Di dalam loop ini , method toString() akan dipanggil untuk setiap user meskipun hasilnya akan dibuang jika logging level debug tidak dilakukan.
Sebagian sistem bahasa memungkinkan kita membuat sistem logging yang zero overhead/zero cost. Artinya: jika fungsi log tidak dipanggil, maka seolah-olah fungsi itu tidak memakai CPU sama sekali. Misalnya di C, logging bisa memakai fitur macro dan jika macro-nya ditulis dengan baik akan bisa menghasilkan zero overhead logging.
Untuk bahasa yang tidak mendukung ini, maka kita pelu mengecek log level saat ini:
if (logger.isDebug() {
//do debug logging
}Selain masalah membuang waktu CPU, log juga sebaiknya tidak membuang disk space. Dalam kasus sistem logging komersial (misalnya datadog), biaya biasanya adalah setiap megabyte log atau setiap n log, jadi dengan hanya logging seperlunya kita tidak mempermahal biaya logging.
Trace Context
Dalam arsitektur dengan berorientasi service (biasanya microservice), ada banyak komponen yang saling berkomunikasi. Kadang komunikasinya synchronous, dan kadang asynchronous, dan masalah bisa terjadi di sistem mana saja. Jika ada sebuah masalah, kita ingin mengetahui asal sebuah transaksi dari mana, dan apa input awalnya.
Agar kita dapat melakukan penelusuran dari mulai transaksi masuk, sebaiknya ada request ID. Jadi jika terjadi masalah di satu service (misalnya billing) kita bisa mengecek request ID di service lain, untuk mengetahui service mana yang mengirimkan data yang menyebabkan error.
Beberapa produk bisa secara otomatis menginjeksikan ID transaksi agar tracing bisa dilakukan otomatis. W3C memiliki standard Trace Context yang isinya adalah standard header HTTP dan format nilai header tersebut untuk mempropagasikan informasi konteks agar kita dapat melakukan skenario tracing terdistribusi.
Penutup
Seringkali programmer mengabaikan atau menyepelekan logging padahal ini merupakan hal penting untuk menyelesaikan masalah pada sistem production.