Belajar strace, gdb and lsof
Setelah nonton dan membaca blog dari Julia Evans megenai strace saya jadi ingin mencoba menggunakan dan mempelajarinya. Namun karena saya adalah orang yang sangat malas, jadi saya tidak pernah mempelajarinya sampai tahun ini (2019).
Di suatu pagi yang mendung, saat saya melihat dashboard dari Timeline, saya melihat ada lonjakan max latency yang tidak pernah turun. Saya coba cari request apa yang memiliki lonjakan tersebut, dan saya menemukan request yang di dalamnya berkomunikasi dengan thumbor.
Saat saya lihat di response time thumbor, saya melihat ada lonjakan latency, namun tidak sebesar lonjakan max latency di Timeline. Jadi saya coba lihat ke dalam log, dan di dalam log nginx, ada beberapa request ke process thumbor di dalam satu instance yang selalu timeout. Dan setelah saya lihat waktunya, saat hal tersebut mulai terjadi, lonjakan max latency juga terjadi di Timeline.
Masalah ini sudah sering terjadi sebelumnya, namun yang saya lihat, setelah deploy thumbor, masalah ini akan hilang. Dan akan muncul kembali dalam waktu yang sangat acak. Pernah terjadi dalam satu minggu setelah deploy, atau satu bulan setelahnya.
Awalnya saya ingin membuat script, agar me-restart process thumbor yang selalu timeout. Namun hal ini dicegah oleh teman saya Yap, saat saya menanyakan ini kepada dia. Dia minta saya untuk masuk ke instance tersebut dan melakukan strace ke process yang selalu timeout.
Debugging masalah tersebut
Alhasil waktu saya pertama kali masuk di tahun ini, masalah tersebut sedang terjadi. Jadi saya tinggal masuk ke instance dan melakukan strace, mudah bukan? Tapi sebelumnya saya ingin tahu, sebenarnya timeout tersebut selalu terjadi? atau masih ada request yang bisa dilakukan seperti health check atau request ke /?
Saya coba curl ke health check endpoint di thumbor, hasilnya menunggu lama dan akhirnya timeout. Saya coba ke endpoint lain, juga timeout. Ya sudah saya coba strace saja.
$ sudo strace -p <PID>
read(38,
strace: Process <PID> detachedhanya ada read dan hang, saya harus melakukan untuk keluar dari strace. Apa itu read? Mengapa thumbor hang pada saat read? Karena saya baru pertama kali kenal strace dan tidak tahu hal itu, saya coba DuckDuckGo hal itu. Namun saya tidak mendapatkan jawaban seperti biasanya. Tidak ada pertanyaan di stackoverflow, ataupun orang yang membuat blog tentang suatu program yang hang pada saat read. Jadi saya kembali kepada Yap untuk menanyakan hal ini.
Saat Yap ke meja saya untuk melihat apa yang terjadi, dia langsung membuka lsof.
$ lsof -p <PID>
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
-- omitted --
thumbor 4423 root 33u sock 0,9 0t0 174820452 protocol: TCP
thumbor 4423 root 34u IPv4 174818209 0t0 TCP thumbor-app-random-fqdn.internal:43800->tm-in-f95.1e100.net:https (CLOSE_WAIT)
thumbor 4423 root 35u sock 0,9 0t0 174821546 protocol: TCP
thumbor 4423 root 36u IPv4 174821551 0t0 TCP thumbor-app-random-fqdn.internal:44130->tm-in-f95.1e100.net:https (ESTABLISHED)
thumbor 4423 root 37u sock 0,9 0t0 174820651 protocol: TCP
thumbor 4423 root 38u IPv4 174819638 0t0 TCP thumbor-app-random-fqdn.internal:44170->tm-in-f95.1e100.net:https (ESTABLISHED)
thumbor 4423 root 40u sock 0,9 0t0 174795750 protocol: TCP
thumbor 4423 root 44u sock 0,9 0t0 174804428 protocol: TCP
thumbor 4423 root 45u IPv4 174804433 0t0 TCP thumbor-app-random-fqdn.internal:33590->tm-in-f95.1e100.net:https (CLOSE_WAIT)
thumbor 4423 root 46u sock 0,9 0t0 174805746 protocol: TCP
thumbor 4423 root 50u sock 0,9 0t0 174809499 protocol: TCP
-- omitted --Lalu membuka gdb
$ sudo gdb -p 4423
(gdb) bt
#0 0x00007f6a5cc6251d in read () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007f6a5aecc3dc in ?? () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#2 0x00007f6a5aeca37c in BIO_read () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#3 0x00007f6a5a95c80a in ?? () from /lib/x86_64-linux-gnu/libssl.so.1.0.0
#4 0x00007f6a5a95e0ad in ?? () from /lib/x86_64-linux-gnu/libssl.so.1.0.0
#5 0x00007f6a5a95ac64 in ?? () from /lib/x86_64-linux-gnu/libssl.so.1.0.0
#6 0x00007f6a5abadb38 in ?? () from /usr/lib/python2.7/lib-dynload/_ssl.x86_64-linux-gnu.so
#7 0x00000000004bc4aa in PyEval_EvalFrameEx ()
#8 0x00000000004b9b66 in PyEval_EvalCodeEx ()
#9 0x00000000004c17c6 in PyEval_EvalFrameEx ()
#10 0x00000000004b9b66 in PyEval_EvalCodeEx ()
#11 0x00000000004c17c6 in PyEval_EvalFrameEx ()
-- omitted --Lalu dia memberitahukan bahwa saya harus mencoba mencari library python yang menggunakan libssl.so. Setelah beberapa jam mencari tahu, akhirnya ketemu library yang menggunakannya adalah requests. Yaitu google-resumable-media-python -> google-cloud-python -> thumbor-cloud-storage.
Sebagai bonus, masalah ini sebenarnya ada di dalam Github issue dari google-cloud-python dan belum di-fix.
Problem sudah kami fix di library plugin thumbor dan saat ini sudah tidak ada masalah tersebut di production. Yeaay!!
Lesson Learned
Setelah menemukan dan men-deploy fix tersebut, saya mulai penasaran, dari mana teman saya itu dapat sampai pada kesimpulan untuk mengecek libssl.
Waktu saya pair dengan dia, dia selalu membuka man lsof, man strace, dan sebagainya. Saya penasaran, saya coba man read. Ternyata read itu adalah system call untuk membaca file descriptor. Definisi file descriptor di dalam Linux adalah sebuah abstract handle untuk mengakses file atau input/output device lainnya (dalam hal ini termasuk network).
Kalau dilihat lebih teliti lagi di atas, Thumbor stuck saat read file descriptor 38, dan dalam lsof, 38 adalah network call ke Google Cloud Storage. Artinya Thumbor hang pada saat melakukan proses download ke GCS.
Saat melihat gdb, hal yang terlihat adalah hang-nya process Thumbor, terakhir saat mengakses libssl, dan beruntungnya google-cloud-python adalah satu-satunya library di mesin itu yang menggunakan requests.
Selalu cari issue kita di github repository dari library yang kita pakai, usahakan untuk mengerti masalah tersebut jika kita menemukannya dan jika issue belum ada yang melaporkan, maka laporkanlah.
Dan yang terakhir man read.