Apa sajakah pola dan anti-pola pencatatan aplikasi? [Tutup]

Baru-baru ini saya harus menyelidiki masalah lapangan untuk aplikasi perusahaan besar kami. Saya merasa ngeri dengan log yang harus saya sisir dalam upaya untuk menemukan masalah dan pada akhirnya log tidak membantu sama sekali mengidentifikasi / mengisolasi bug.

Catatan: Saya mengerti tidak semua bug dapat ditemukan melalui log. Ini tidak mengubah fakta bahwa log itu mengerikan.

Ada beberapa masalah nyata dengan pencatatan kami yang sudah dapat kami coba perbaiki. Saya tidak ingin mencantumkannya di sini dan saya tidak bisa hanya memperlihatkan kepada Anda file log kami sehingga Anda dapat memberikan saran tentang apa yang harus dilakukan.

Sebagai gantinya, untuk menilai seberapa buruk yang kami lakukan di sisi penebangan, saya ingin tahu:

1. Apa sajakah pedoman , jika ada, ketika datang ke log untuk aplikasi, terutama aplikasi besar.
2. Apakah ada pola yang harus kita ikuti atau anti-pola yang harus kita perhatikan?
3. Apakah ini hal yang penting untuk diperbaiki atau bahkan dapat diperbaiki atau semua file log cukup besar dan Anda perlu skrip tambahan untuk menganalisisnya?

Catatan: kami menggunakan log4j.

Beberapa poin yang terbukti bermanfaat bagi praktik saya:

• Simpan semua kode logging di kode produksi Anda. Memiliki kemampuan untuk mengaktifkan logging produksi yang lebih / kurang terperinci, lebih disukai per subsistem dan tanpa memulai kembali program Anda.

• Buat log mudah diurai dengan grepdan dengan mata. Menempel beberapa bidang umum di awal setiap baris. Identifikasi waktu, tingkat keparahan, dan subsistem di setiap baris. Merumuskan pesan dengan jelas. Buat setiap pesan log mudah dipetakan ke baris kode sumbernya.

• Jika kesalahan terjadi, cobalah untuk mengumpulkan dan mencatat sebanyak mungkin informasi. Mungkin butuh waktu lama tapi tidak apa-apa karena proses normal gagal. Tidak harus menunggu ketika kondisi yang sama terjadi dalam produksi dengan debugger terlampir sangat berharga.

Log sebagian besar dibutuhkan untuk pemantauan dan pemecahan masalah. Tempatkan diri Anda pada posisi pemecah masalah dan pikirkan jenis log apa yang ingin Anda miliki ketika sesuatu yang salah terjadi atau telah terjadi di tengah malam.

Saya bekerja dengan sistem waktu-kritis kritis keselamatan dan penebangan seringkali merupakan satu-satunya cara untuk menangkap bug langka yang muncul sekali bulan biru pada setiap Selasa ke-53 ketika bulan purnama, jika Anda mengetahui maksud saya. Jenis ini membuat Anda terobsesi dengan subjek, jadi saya akan minta maaf sekarang jika saya mulai berbusa. Berikut ini ditulis untuk log debug kode asli, tetapi sebagian besar berlaku untuk dunia yang dikelola juga ...

Gunakan file log teks. Tampak jelas, tetapi beberapa orang memang mencoba membuat file log biner: itu hanya bodoh karena saya tidak perlu mencari alat pembaca ketika saya berada di lapangan. Ditambah lagi jika itu teks dan debugnya bertele-tele, ada kemungkinan insinyur lapangan dapat membaca file dan mendiagnosis masalahnya tanpa pernah kembali kepada saya. Semua orang menang.

Saya merancang sistem yang mampu mencatat hampir semua hal, tetapi saya tidak mengaktifkan semuanya secara default. Informasi debug dikirim ke dialog debug tersembunyi yang mencatat waktu dan mengeluarkannya ke kotak daftar (terbatas pada sekitar 500 baris sebelum dihapus), dan dialog memungkinkan saya untuk menghentikannya, menyimpannya ke file log secara otomatis, atau mengalihkannya ke debugger terlampir. Pengalihan itu memungkinkan saya untuk melihat hasil debug dari beberapa aplikasi yang semuanya terserialisasi dengan rapi, yang kadang-kadang bisa menjadi penyelamat. Saya biasa menggunakan level logging numerik (semakin tinggi Anda mengatur level, semakin banyak yang Anda tangkap):

off
errors only
basic
detailed
everything

tetapi ini terlalu tidak fleksibel - saat Anda berusaha menuju bug, jauh lebih efisien untuk dapat fokus masuk pada apa yang Anda butuhkan tanpa harus melalui banyak detritus, dan itu mungkin merupakan satu jenis transaksi atau operasi tertentu yang menyebabkan kesalahan. Jika itu mengharuskan Anda untuk mengaktifkan semuanya, Anda hanya membuat pekerjaan Anda sendiri lebih sulit. Anda membutuhkan sesuatu yang lebih halus.

Jadi sekarang saya sedang dalam proses beralih ke logging berdasarkan sistem bendera. Segala sesuatu yang dicatat memiliki tanda yang merinci operasi apa itu, dan ada satu set kotak centang yang memungkinkan saya untuk menentukan apa yang dicatat. Biasanya daftar itu terlihat seperti ini:

#define DEBUG_ERROR          1
#define DEBUG_BASIC          2
#define DEBUG_DETAIL         4
#define DEBUG_MSG_BASIC      8
#define DEBUG_MSG_POLL       16
#define DEBUG_MSG_STATUS     32
#define DEBUG_METRICS        64
#define DEBUG_EXCEPTION      128
#define DEBUG_STATE_CHANGE   256
#define DEBUG_DB_READ        512
#define DEBUG_DB_WRITE       1024
#define DEBUG_SQL_TEXT       2048
#define DEBUG_MSG_CONTENTS   4096

Sistem logging ini dikirimkan dengan rilis build, dihidupkan dan disimpan ke file secara default. Sudah terlambat untuk mengetahui Anda seharusnya login SETELAH bug telah terjadi, jika bug itu hanya terjadi setiap enam bulan rata-rata dan Anda tidak memiliki cara untuk mereproduksinya. Logging yang hanya berfungsi dengan debug build saja. polos. bodoh.

Perangkat lunak biasanya dikirimkan dengan ERROR, BASIC, STATE_CHANGE dan EXCEPTION dihidupkan, tetapi ini dapat diubah di lapangan melalui dialog debug (atau pengaturan registri / ini / cfg, di mana hal-hal ini disimpan).

Oh dan satu hal - sistem debug saya menghasilkan satu file per hari. Persyaratan Anda mungkin berbeda. Tetapi pastikan kode debug Anda memulai setiap file dengan tanggal, versi kode yang Anda jalankan, dan jika mungkin beberapa penanda untuk ID pelanggan, lokasi sistem atau apa pun. Anda bisa mendapatkan mash-mash file log yang datang dari lapangan, dan Anda perlu beberapa catatan tentang apa yang datang dari mana dan versi sistem apa yang mereka jalankan yang sebenarnya ada dalam data itu sendiri, dan Anda tidak bisa mempercayai pelanggan / insinyur lapangan untuk memberi tahu Anda versi apa yang mereka miliki - mereka mungkin hanya memberi tahu Anda versi apa yang mereka miliki. Lebih buruk lagi, mereka dapat melaporkan versi exe yang ada di disk, tetapi versi lama masih berjalan karena mereka lupa untuk reboot setelah mengganti. Minta kode Anda memberitahu Anda sendiri.

Terakhir, Anda tidak ingin kode Anda menghasilkan masalah sendiri, jadi masukkan fungsi pengatur waktu untuk membersihkan file log setelah berhari-hari atau berminggu-minggu (cukup periksa perbedaan antara waktu sekarang dan waktu pembuatan file). Ini OK untuk aplikasi server yang berjalan sepanjang waktu, pada aplikasi sisi klien Anda bisa bertahan dengan membersihkan data lama saat Anda memulai. Kami biasanya membersihkan setelah 30 hari atau lebih, pada sistem tanpa kunjungan insinyur yang sering Anda ingin meninggalkannya lebih lama. Jelas ini tergantung pada ukuran file log Anda juga.

Sumber daya publik favorit saya untuk panduan logging adalah Apache JCL Best Practices .

Praktik terbaik untuk JCL disajikan dalam dua kategori: Umum dan Perusahaan. Prinsip-prinsip umum cukup jelas. Praktik perusahaan sedikit lebih terlibat dan tidak selalu sejelas mengapa mereka penting.

Prinsip praktik terbaik Perusahaan berlaku untuk komponen dan perkakas middleware yang diharapkan dijalankan di lingkungan tingkat "Perusahaan". Masalah-masalah ini berkaitan dengan Penebangan sebagai Internasionalisasi, dan deteksi kesalahan. Perusahaan membutuhkan lebih banyak usaha dan perencanaan, tetapi sangat dianjurkan (jika tidak diperlukan) dalam sistem tingkat produksi. Perusahaan / lingkungan perusahaan yang berbeda memiliki persyaratan yang berbeda, sehingga menjadi fleksibel selalu membantu ...

Meskipun menargetkan JCL, ini tampaknya cukup umum untuk diadopsi untuk logging secara umum.

• ^{"Pedoman" pribadi saya untuk logging adalah bahwa pada level debug, saya mencoba membuat log saya dibaca seperti cerita - dengan logika yang dapat dimengerti dan detail yang cukup (tetapi tidak kelebihan beban).}

Anti-pola yang paling terkenal mungkin adalah "menelan pengecualian" - cari saja di web.

Adapun file logging besar, dalam praktik saya ini kebanyakan kasus normal. Dan ya, skrip tambahan seperti yang Anda panggil dan / atau alat seperti Chainsaw juga terlihat normal bagi saya.

• ^{Di atas tidak berarti bahwa Anda harus selalu membabi buta menaruh semua log dalam satu file besar. Terkadang berguna untuk menulis / menyalin beberapa log untuk memisahkan file. Misalnya dalam proyek saya baru-baru ini, QA meminta file khusus untuk metrik dan data waktu serta laporan singkat tentang operasi sistem. Mereka mengatakan mereka akan mendapat manfaat dari itu dan dev melakukannya (manfaat dari file laporan singkat ternyata memang signifikan).}

PS. Mengenai anti-pola, orang lain yang muncul dalam pikiran adalah "banjir" dan pesan tidak masuk akal.

• Saya menyebutnya flooding ketika saya melihat beberapa pesan serupa datang dari satu loop dengan banyak iterasi. Bagi saya, flooding cukup mengganggu untuk mencoba menghilangkannya ketika saya mendeteksinya dalam kode sumber. Biasanya memperbaikinya memerlukan beberapa seni - karena, well, hal-hal yang terjadi dalam loop mungkin menarik. Ketika saya tidak punya waktu untuk memperbaikinya lebih dalam, saya mencoba untuk setidaknya mengubah tingkat logging dari pesan tersebut ke yang terendah untuk membuatnya lebih mudah untuk disaring.

• Pesan tidak masuk akal tampaknya menjadi sampah yang cukup populer. Ini terlihat tidak berbahaya ketika dibaca dalam kode sumber - saya kira kita harus melalui rasa sakit menganalisis keluaran debug yang tampak seperti ...

  step #1
  step #2
  step #3
  

  ... sangat menghargai keburukan bawaan mereka. Heuristik favorit saya untuk mendeteksi masalah semacam ini pada tingkat kode sumber (diusulkan oleh rekan di salah satu proyek saya di masa lalu) adalah menghitung jumlah kemunculan simbol ruang dalam string literal yang digunakan dalam logging. Dalam pengalaman saya, nol spasi pada dasarnya menjamin pernyataan logging tidak masuk akal, satu spasi juga merupakan indikator yang baik untuk masalah potensial.

Catat pengecualian hanya sekali!

Salah satu poin rasa sakit umum yang saya perhatikan adalah mencatat dan memikirkan kembali pengecualian. Akibatnya, file log berisi pengecualian yang sama beberapa kali pada beberapa level stack.

Berikut ini adalah anti-pola: Membuat dua lusin bidang "generik" dalam tabel database untuk melacak apa pun yang mungkin dan kemudian memiliki 88 (dan menghitung) nilai enum yang berbeda untuk berbagai jenis log.

Pengalaman saya dengan log adalah semakin besar semakin baik, tetapi cukup konsisten untuk membuatnya difilter oleh mesin, dan dapat mengkonfigurasi tingkat keparahan untuk setiap komponen aplikasi Anda secara individual.

Juga, sangat sulit untuk memprediksi logging apa yang Anda perlukan untuk menemukan bug di masa depan. Sebagian besar tempat yang jelas untuk mencatat bug diperbaiki sebelum produk keluar. Tidak jarang hasil laporan bug adalah bahwa Anda baru saja menambahkan logging untuk membantu mendiagnosisnya jika itu terjadi lagi.

Beberapa catatan dari sisi operasi rumah di sini:

1) Pastikan log dapat dikonfigurasi secara lokal, lebih disukai dengan alat yang tidak lebih berat dari editor teks. Sebagian besar waktu kami tidak ingin mendapatkan pencatatan level TRACE, tetapi kami senang dapat mengaktifkannya.

2) Jika memungkinkan, pastikan log dapat dibaca dengan alat yang tidak lebih berat dari editor teks. Tidak ada yang lebih buruk daripada harus pergi berburu alat pada jam yang aneh ketika sistem produksi gagal.

Dari pengalaman saya sendiri bekerja dengan aplikasi web:

(& mempertimbangkan penyimpanan sangat murah sekarang-hari)

• Log sebanyak mungkin info yang tersedia (pada saat itu).
• Saya selalu memasukkan DateTime. Sekarang di log-string saya.
• Saya selalu (jika mungkin) mencatat durasi waktu "aksi" tertentu.

• Konsisten dengan log-string Anda. Karena saya selalu menggunakan pola seperti ini:

  • "[Info X] [Info Y] [Info Z] [dll]"

Terlepas dari stacktrace, catat status aplikasi saat ini dan inputnya.

Perangkat lunak bersifat deterministik, keduanya biasanya merupakan satu-satunya hal yang Anda perlukan untuk mereproduksi bug. Menyimpan status penuh mungkin dalam beberapa kasus menyusahkan sehingga cara untuk mereproduksi status saat ini, misalnya dengan input sebelumnya, juga baik.

Tentu saja lebih banyak data selalu lebih baik tetapi setidaknya keduanya adalah awal yang baik untuk crash yang paling mudah.