Sebuah Kisah Coredump Tentang NGINX ctx dan error_page

Coredumps di lingkungan produksi sangat menakutkan bagi para insinyur, terutama ketika crash terjadi di tengah malam. Saya sendiri mengalaminya lebih dari satu dekade yang lalu. Mencoba menemukan "bug hantu" ini yang hanya muncul di malam hari, seluruh tim pulang ke rumah untuk tidur di siang hari dan kembali ke perusahaan pada pukul 12 malam untuk menunggu crash dan memeriksa setiap layanan satu per satu. Bayangkan malam yang gelap dan gedung perkantoran dengan hanya beberapa workstation yang menyala, menatap monitor yang terus berdetak untuk data dan log – pengalaman yang intens dan mendebarkan. Kami bertahan selama tiga malam sebelum menemukan bug dan menyelesaikannya, yang merupakan pengalaman yang tak terlupakan.

Tidak disangka, kami akan mengalaminya sekali lagi. Hanya saja kali ini bukan layanan kami sendiri, tetapi layanan online klien yang mengalami coredump. Ini lebih menantang daripada lingkungan kami sendiri yang dapat dikendalikan:

• Kesalahan hanya terjadi di lingkungan produksi pengguna, dan pengguna tidak dapat mereproduksi kesalahan bahkan di lingkungan pra-produksi dan lingkungan pengujian mereka sendiri.
• Pengguna memiliki kode kustom di atas Apache APISIX sumber terbuka, yang tidak terlihat sampai NDA ditandatangani secara terpisah.
• Tidak dapat menambahkan log debug.
• Kesalahan hanya terjadi pada pukul 3 pagi, sehingga membutuhkan sumber daya tambahan dari klien untuk segera ditangani.

Singkatnya, masalah ini tidak dapat direproduksi, tidak memiliki kode sumber lengkap, dan tidak ada lingkungan untuk menguji. Namun, kami harus menemukan kesalahan, menemukan cara untuk mereproduksi, dan memberikan perbaikan akhirnya. Selama proses ini, kami menghadapi banyak tantangan dan belajar banyak darinya. Di sini kami memposting beberapa poin menarik yang ditemui selama proses debugging. Saya harap ini akan memberikan beberapa panduan ketika orang melakukan debugging untuk NGINX dan APISIX.

Deskripsi Masalah

Setelah pengguna mengupgrade APISIX dari versi 2.4.1 ke versi 2.13.1, coredumps terjadi secara siklis, dengan pesan kesalahan berikut:

Dari pesan coredump, kita dapat melihat bahwa segmentation fault terjadi di lua-var-nginx-module. Dan berikut adalah data yang sesuai (sebagian) di memori:

#0  0x00000000005714d4 in ngx_http_lua_var_ffi_scheme (r=0x570d700, scheme=0x7fd2c241a760)
    at /tmp/vua-openresty/openresty-1.19.3.1-build/openresty-1.19.3.1/../lua-var-nginx-module/src/ngx_http_lua_var_module.c:152
152        /tmp/vua-openresty/openresty-1.19.3.1-build/openresty-1.19.3.1/../lua-var-nginx-module/src/ngx_http_lua_var_module.c: No such file or directory.
(gdb) print *r
$1 = {signature = 0, connection = 0x0, ctx = 0x15, main_conf = 0x5adf690, srv_conf = 0x0, loc_conf = 0x0, read_event_handler = 0xe, write_event_handler = 0x5adf697,
  cache = 0x2, upstream = 0x589c15, upstream_states = 0x0, pool = 0x0, header_in = 0xffffffffffffffff}

Kita dapat melihat bahwa data di memori memiliki masalah.

Beberapa Pemikiran Sebelum Analisis

Segmentation fault biasanya terjadi dalam dua skenario:

1. Membaca/menulis alamat yang tidak valid di memori, seperti mengakses indeks array di luar batas, segmentation fault terjadi segera.
2. Melakukan penulisan yang tidak valid tetapi memodifikasi alamat yang valid, sehingga tidak menghasilkan segmentation fault segera. Selama program berjalan, ia mencoba mengakses data di alamat yang salah dan menghasilkan segmentation fault. Misalnya, ketika nilai pointer diubah secara salah, nanti ketika kita mengakses pointer ini, itu mungkin memicu segmentation fault.

Untuk skenario pertama, masalah dapat dengan mudah ditemukan jika kita memeriksa call stack.

Untuk skenario kedua, karena tidak jelas di mana kesalahan terjadi pertama kali, kode yang menghasilkan kesalahan dan kode yang memicu segmentation fault mungkin tidak berada di lokasi yang sama, bahkan sama sekali tidak terkait, sehingga sulit untuk ditemukan. Kita hanya bisa mengumpulkan lebih banyak informasi konteks yang melibatkan crash, seperti:

• Detail konfigurasi APISIX saat ini.
• Tahap pemrosesan permintaan saat ini.
• Detail permintaan saat ini.
• Jumlah koneksi bersamaan.
• Log kesalahan.

Melalui informasi ini, kami akan mencoba menemukan bug dengan meninjau kode dan menemukan cara untuk mereproduksi masalah.

Analisis

1. Pemeriksaan Konteks Kesalahan

Setelah analisis yang cermat, kami menemukan bahwa kesalahan biasanya terjadi antara pukul 3 pagi dan 4 pagi, dengan pesan kesalahan coredump berikut:

Akhirnya, kami menyadari bahwa log kesalahan terkait dengan operasi pengguna. Karena alasan tertentu, semua pesan upstream akan dihapus pada saat ini. Jadi, kami menduga bahwa masalah terkait dengan operasi clear/reset upstream, dan coredump mungkin disebabkan oleh masuk ke cabang pengecualian setelah kesalahan kembali.

2. Mendapatkan Call Stack Lua

Karena GDB tidak dapat melacak call stack Lua, kami tidak dapat menemukan panggilan mana yang menghasilkan kesalahan. Jadi, hal pertama yang perlu kami lakukan adalah mendapatkan call stack Lua; kami memiliki dua metode untuk mendapatkan call stack:

1. Di perpustakaan lua-var-nginx-module tambahkan kode untuk mencetak call stack (print(debug.traceback(...)). Kelemahannya adalah itu akan menghasilkan banyak log kesalahan, berdampak negatif pada lingkungan produksi.
2. Gunakan openresty-gdb-utils yang dikelola oleh API7.ai, toolkit ini menggunakan DSL GDB dan ekstensi python untuk meningkatkan kemampuan gdb dalam menganalisis call stack Lua. Catatan, Anda perlu mengaktifkan simbol debug pada waktu kompilasi. Ini secara default disertakan dalam APISIX.

Kemudian, kami mendapatkan call stack berikut.

Menggabungkan call stack Lua dan C, kami dapat menemukan bahwa coredump terjadi karena pengguna memanggil ngx.ctx.api_ctx.var.scheme di plugin Prometheus. Namun, alasan crash masih belum jelas, kami perlu menganalisisnya lebih lanjut.

3. Cache Menyebabkan Masalah

Kesalahan terjadi saat mengakses variabel dari ngx.ctx.api_ctx.var yang menjalankan panggilan di lua-var-nginx-module yang dijelaskan di atas. Untuk meningkatkan efisiensi, itu menyimpan cache permintaan saat ini. Kami ingat kesalahan terjadi ketika nilai badan permintaan memiliki pengecualian, sehingga validitas permintaan yang di-cache juga dipertanyakan. Untuk memverifikasi pemikiran ini, kami menghentikan program dari mengambil memori yang di-cache, tetapi mengambil ulang permintaan setiap kali.

else
    --val = get_var(key, t._request)
    val = get_var(key, nil)              <============ t._request diubah menjadi nil
end

Pengguna menguji dengan versi yang dimodifikasi ini sepanjang malam, dan kesalahan tidak terjadi lagi; kami memverifikasi bahwa badan permintaan memiliki masalah.

4. Kesalahan di ngx.ctx

Badan permintaan yang di-cache disimpan di ngx.ctx, dan satu-satunya tempat yang memodifikasi ngx.ctx adalah di apisix/init.lua.

function _M.http_header_filter_phase()
    if ngx_var.ctx_ref ~= '' then
        -- mencegah kebocoran tabel
        local stash_ctx = fetch_ctx()

        -- pengalihan internal, jadi kita harus menerapkan ctx
        if ngx_var.from_error_page == "true" then
            ngx.ctx = stash_ctx          <================= DI SINI
        end
    end

    core.response.set_header("Server", ver_header)

    local up_status = get_var("upstream_status")
    if up_status then
        set_resp_upstream_status(up_status)
    end

Mengapa kita perlu memulihkan ngx.ctx di sini? Karena ngx.ctx disimpan di registry Lua, ngx.ctx yang sesuai dapat ditemukan melalui indeks registry. Dan indeks tersebut disimpan di anggota ctx dari struktur permintaan NGINX. Setiap kali pengalihan internal dilakukan, NGINX akan menghapus ctx, dan dengan demikian indeks tidak dapat ditemukan.

Untuk mengatasi masalah ini, APISIX membuat tabel, tabel menyimpan ngx.ctx saat ini sebelum pengalihan, dan kemudian menggunakan ngx.var untuk mencatat indeks ngx.ctx di tabel ini, setiap kali perlu dipulihkan, kita bisa mendapatkan ngx.ctx langsung dari tabel.

Kode pada gambar di atas hanya dipicu ketika pengguna mengonfigurasi instruksi error_page, dan setelah kesalahan terjadi setelah pengalihan internal.

Dan kami tahu persis bahwa pengguna mengaktifkan instruksi error_page setelah upgrade versi, digabungkan dengan kesalahan yang terjadi dari perubahan upstream yang kami jelaskan di atas. Semuanya tampak terhubung. Apakah sebenarnya ngx.ctx yang menciptakan bug selama proses penanganan kesalahan?

5. Mengapa ngx.ctx Memiliki Bug

Dengan pertanyaan itu, kami memeriksa kode ngx.ctx yang terkait dengan pencadangan, dan kami menemukan masalah yang lebih aneh. Setelah gagal di set_upstream, itu tidak akan mengambil langkah pemulihan ngx.ctx, karena keluar lebih awal, itu tidak akan mencadangkan ngx.ctx, dan juga tidak akan masuk ke proses pemulihan.

Ini jelas sebuah bug! Nah, ini karena ngx.ctx perlu dipulihkan setelah pengalihan. Dan bagaimana proses ini memulihkan ngx.ctx? Di mana ngx.ctx salah sejak awal? Sekarang ada terlalu banyak ketidakpastian, kami perlu mengumpulkan lebih banyak data.

Setelah berdiskusi, kami menambahkan log kedua di produksi, dan kami menemukan bahwa, ketika kesalahan terjadi setelah pengalihan internal, ngx.ctx tidak melalui proses pemulihan, melainkan menyebabkan coredump langsung!

Ini adalah fenomena yang membingungkan karena jika ngx.ctx tidak dipulihkan setelah pengalihan, ngx.ctx akan kosong/null. Dan ada kode yang memeriksa nilai kosong; seharusnya tidak memicu kode coredump di plugin.

local function common_phase(phase_name)
    local api_ctx = ngx.ctx.api_ctx
    if not api_ctx then              <============ DI SINI
        return
    end

    plugin.run_global_rules(api_ctx, api_ctx.global_rules, phase_name)

Jadi, apakah pengalihan internal error_page ini yang menyebabkan ngx.ctx memiliki masalah?

6. Kesimpulan Awal

Setelah menganalisis dan memeriksa, kami mendapatkan pemahaman dasar tentang proses yang salah.

set_upstream gagal dan dialihkan ke tahap pemrosesan kesalahan error_page, dan ngx.ctx yang diharapkan kosong memiliki nilai yang tidak terduga. Dan karena bug APISIX, itu tidak memulihkan ngx.ctx sebelum pengalihan, menyebabkan ngx.ctx memiliki data kotor saat diakses, sehingga menyebabkan coredump. Untuk mengatasi masalah ini, kita hanya perlu memulihkan ngx.ctx setelah pengalihan; implementasi detail dari commit ini disediakan di akhir artikel untuk referensi.

Meskipun kami memberikan perbaikan untuk bug ini, kami masih belum dapat memahami logika lengkap dari bug tersebut. Karena pengguna tidak memodifikasi logika ngx.ctx, versi sumber terbuka seharusnya dapat mereproduksi. Agar tidak terus memengaruhi lingkungan produksi dan proses penyebaran pengguna, kami memutuskan untuk terus menyelidiki akar penyebabnya.

7. Reproduksi yang Berhasil

Dari apa yang kami ketahui, kami tidak dapat mereproduksi masalah. Setelah analisis, kami memutuskan untuk memeriksa dua tempat berikut:

• Apakah pengalihan internal memiliki cabang khusus untuk pemrosesan?
• Apakah ngx.ctx memiliki cabang khusus untuk pemrosesan?

Untuk poin pertama, selama pemrosesan setiap modul filter NGINX, mungkin ada beberapa cabang pengecualian yang memengaruhi anggota ctx dari badan permintaan, sehingga memengaruhi ngx.ctx. Kami memeriksa modul pengguna yang dikompilasi ke NGINX untuk potensi cabang pengecualian tetapi tidak menemukan masalah serupa.

Untuk poin kedua, setelah penyelidikan, kami menemukan bahwa selama SSL handshake, ngx.ctx memiliki masalah dari penggunaan kembali. Jika tahap HTTP tidak dapat memperoleh ngx.ctx, itu akan mencoba memperolehnya dari tahap SSL. Tahap SSL memiliki ngx.ctx sendiri, dan itu mungkin menyebabkan masalah untuk ngx.ctx.

Berdasarkan penemuan di atas, kami merancang kondisi berikut, dan berhasil mereproduksi masalah:

1. Versi APISIX yang sama dengan pengguna
2. Aktifkan sertifikat SSL
3. Buat kesalahan internal yang memicu error_page (seperti meminta upstream ketika tidak ada)
4. Koneksi panjang
5. Plugin Prometheus (coredump terjadi di plugin untuk pengguna)

Kami akhirnya membuat batu bata tanpa jerami. Melalui dugaan dan verifikasi, kami akhirnya memahami proses lengkap dari bug ini. Setelah ada reproduksi lengkap, tidak sulit lagi untuk menyelesaikan masalah, dan proses akhir tidak akan dijelaskan secara detail di sini. Saya yakin bahwa semua orang memiliki banyak pengalaman dalam masalah yang dapat direproduksi dengan akurat.

Ringkasan

Akar penyebab masalah ini: karena ngx.ctx tidak dipulihkan setelah masuk ke error_page, semua permintaan pada koneksi panjang menggunakan kembali ngx.ctx yang sama di fase SSL. Akhirnya, menyebabkan ngx.ctx memiliki data kotor dan coredump dihasilkan.

Dalam tindak lanjut, kami juga mengusulkan solusi yang sesuai untuk masalah ini: memastikan bahwa ngx.ctx dapat dipulihkan secara normal setelah pengalihan internal. Silakan merujuk ke PR spesifik.

Jika APISIX Anda menggunakan fungsi yang melibatkan pengalihan internal seperti error_page, segera upgrade ke versi terbaru.

Menulis program dan debugging adalah tugas yang ilmiah dan ketat, tidak ada ruang untuk ambiguitas. Untuk menyelesaikan masalah, kita perlu mengumpulkan informasi, melacak semua petunjuk potensial, menganalisis call stack, dan kemudian memahami konteks untuk mereproduksi kesalahan. Akhirnya, masalah terpecahkan.