Using Strace to Debug Your Stuck Commands

January 23, 2022

Strace is a useful diagnostic, instructional, and debugging tool. System administrators, diagnosticians and trouble-shooters will find it invaluable for solving problems with programs for which the source is not readily available since they do not need to be recompiled in order to trace them.

Dalam tulisan saya kali ini, saya akan menceritakan sebuah "mejik~~" tool yang sudah menyelamatkan Production cluster berisikan lebih dari 1000 VMs

TL;DR

Di sebuah pagi ketika saya baru saja sampai di kantor untuk on-site. Saya melakukan pengecekan terhadap CEPH cluster (dikarenakan sebelumnya sedang proses recovery slow ops osd) dengan menggunakan perintah :

ubuntu@xxxxxxxxxxxx ~$ ceph -s
  cluster:
    id:     xxxxx-xx-xxx-xxxx-xxxxxxx
    health: HEALTH_WARN
            500011 slow ops, oldest one blocked for 104335 sec, [mon.xxxxx-01,mon.xxxxx-02,mon.xxxxx-03] has slow ops

Saya melihat adanya slow ops hanya ada pada ceph-mon, "berarti slow ops osd sebelumnya, sudah resolved" pikir saya.

Kemudian saya memeriksa systemd di setiap host ceph monitor, dan menemukan bahwa systemd ceph-mon pada host xxxxx-02 inactive (Dead).

ubuntu@xxxxx-02:~$ systemctl status ceph-mon@xxxxx-02
● [email protected] - Ceph cluster monitor daemon
   Loaded: loaded (/lib/systemd/system/[email protected]; disabled; vendor preset: enabled)
   Active: inactive (dead) since Mon 2022-01-24 02:32:16 WIB; 15 hours ago
 Main PID: 875486 (ceph-mon)
    Tasks: 27
   CGroup: /system.slice/system-ceph\x2dmon.slice/[email protected]
           └─875486 /usr/bin/ceph-mon -f --cluster ceph --id xxxxx-02 --setuser ceph --setgroup ceph

Namun ketika dilakukan pengecekan menggunakan ps aux | grep ceph-mon binary /usr/bin/ceph-mon running. Dapat disimpulkan bahwa ceph-mon pada host xxxxx-02 running, namun tidak di bawah pantauan systemd.

Sehingga saya putuskan untuk kill pid ceph-mon yang running tersebut

sudo kill -9 {pid-ceph-mon}

Seketia saya tekan tombol ENTER, "Klakk...." tiba-tiba command ceph tidak bisa dieksekusi alias stuck.

Dalam hati saya berkata "Oh mungkin leader mon-nya pindah tungguin aja... Sambil saya meng-aktifkan systemd ceph-mon pada host xxxxx-02"

Setelah menunggu 10-30 menit, command ceph masih tidak bisa dijalankan alias masih stuck.

Dalam hati saya berkata "Wadoohh, napa ni yakkk!!"

Troubleshoot

1. Check Systemd Status

Langkah pertama yang saya lakukan adalah melakukan pengecekan pada systemd ceph-mon di semua Host.

for i in xxxxx-01 xxxxx-02 xxxxx-03 ; do ssh "systemctl status ceph-mon@$i" ; done

Hasilnya semua running well.

2. Check Leader via admin socket ceph-mon

Pada dasarnya ceph perlu memiliki 2 ceph-mon yang qorum agar bisa berjalan normal.

root@xxxxx-03:/home/ubuntu# ceph--admin-daemon/var/run/ceph/ceph-mon.xxxxx-03.asok mon_status
{
    "name": "xxxxx-03".
    "rank": 1,
    "state": "leader"
    "election_epoch": 15370,
    "quorum": [
        1,
        2
    ],
}

Dapat terlihat bahwa terdapat 2 ceph-monitor yang qorum, sehingga secara teori, ceph seharusnya berjalan sebagaimana mustinya.

Mengumpat di dalam hati "█████ kenapa kagak bisa dahhh..."

3. Ceph command dengan Sepesifik Monitor

Salah satu kolega saya Aji Arya menyarankan untuk melakukan percobaan menjalalankan command dengan argumen -m yang akan membuat ceph menembak ke sepesifik monitor.

ceph -s -m 172.x.238.56

172.x.238.56 merupakan IP segment ceph monitor milik xxxxx-03, seharusnya jika memang monitor tersebut sebagai leader, ceph command bisa dijalankan. Namun hasilnya teteap stuck.

4. Despreate

Setelah 8 jam berdiskusi dengan para kolega, dan lain-lain. Saya merehatkan diri "toh VM exsisting tidak ada yang ter-impact saat itu" dan saya masih berfikiran bahwa itu hanya kasus di mana storedb ceph-mon yang tinggi sedang compacting istilah kasarnya "lagi ngejar (nge-sync) ituu, storedb ceph-mon nyaa.."

"Troubleshoot dilanjutkan oleh para kolega lain"

Hingga saya bagun di pagi hari, dan melanjutkan hidup, dikarenakan hari itu adalah hari sabtu., dan saya adalah manusia normal yang selayaknya perlu malam mingguan.

"Namun semesta berkata lain, malam minggu saya harus berada di depan laptop..."

5. Strace & Debug mode

"Saya join troubleshoot lagi karena ~~disuruh~~ penasaran, bersama CEO saya."

Se-dari awal, saya sudah mencoba menjalalankan command ceph -s --debug-mode=99 yang mana artinya menggunakan mode debug paling "nge-poooll.." namum tidak muncul apa-apa.

"Kalo mode debug aja nga muncul apa-apa gimana mau debug dah..."

Hingga saya menemukan kasus yang sama di Mailing Lists - Ceph, dan dalam kasus tersebut beliau menyarankan melakukan debug menggunakan strace.

"Meskipun di hari sebelumnya saya sudah mencoba menggunakan tools tersebut, namun tidak saya perhatikan dengan teliti, karena output-nya yang musing-innn.."

Kemudian saya memikiran skenario apa yang harus dicoba, dan saya mendapatkan sebuah ide.

$ sudo strace -f ceph -s --debug-ms=99 -m 172.x.238.56
[....]
pid 3052239] connect(12, {sa_family=AF_INET sin_port=ntons(3300),sin_addr-inet_addr("172.xx.238.56")}, 16 sunfinished
pid 3052240] <... fentl resumed» ) = 0x2 (flags O_RDAR)
pid 3052239] <... connect resumed ) -1 ECONNREFUSED (Connection refused)
pid 3052240] fcntl(13, F_SETFL, O_RDWRIO_NONBLOCK) = 0
pid 3052239] futex(0x7fcb9805d8e4, FUTEX_MAKE_PRIVATE, 2147483647 «unfinished
pid 3052240] setsockopt(13, SOL_TCP, TCP NODELAY, [1], 4 «unfinished
pid 3052241] <.... futex resumed)=0
pid 3052240] <... setsockopt resumed> ) = 0
pid 3052241] futex(0x7fcb9805d890, FUTEX_WAIT_PRIVATE, 2, NULL ‹unfinished ...>
pid 3052240] connect(13, {sa_family=AF_INET, sin_port-htons(6789), sin_addr-inet_addr("172.xx.238.56")}, 16 sunfinished
pid 3052239] <... futex resumed ) = 1
pid 3052239] futex(0x7fcb9805d890, FUTEX_WAKE_PRIVATE, 1 «unfinished ...>
pid 3052240] <..connect resumed)= -1 EINPROGRESS (Operation now in progress)
pid 3052241] <... futex resumed )
pid 3052240] poll_ctl(9, EPOLL_CTL_ADD, 13, {EPOLLINIEPOLLET, {u32-13, 464=13}} cunfinished
pid 3052241] futex(0x7fcb9805d890, FUTEX_WAKE_PRIVATE, 1 unfinished .
pid 3052240] <..• epol1_ctl resumedo ) = 0
pid 3052241] <... futex resumed )= 0
pid 3052240] connect (13, [sa_family-AF_INET,sin_port-htons(6789),sin_addrainet_addr("172.xx.238.56")}, 16 unfinished
pid 3052241] futex(0x7fcb9805d8e0, FUTEX_WAIT_PRIVATE, 0, NULL cunfinished
pid 3052240] <.connect resumed)= -1 ECONNREFUSED (Connection refused)
pid 30522391 <..futex resumed )
[....]

Dan saya notice sesuatu yang janggal, "Lohh... kok refused", buru-buru saya check apakah semua ceph-mon hidup, dan running pada port tersebut.

# Check LISTEN Port ceph-mon
for i in xxxxx-01 xxxxx-02 xxxxx-03; do echo $i;ssh $i "sudo lsof -i -P -n | grep LISTEN|grep 6789";done
for i in xxxxx-01 xxxxx-02 xxxxx-03; do echo $i;ssh $i "sudo lsof -i -P -n | grep LISTEN|grep 3300";done

Hasil pengecekan menunjukkan bahwa ternyata ceph-mon running bukan di segment IP yang sebagaimana mustinya.

Posisi Binding Port Ceph Mon
- xxxxx-01  =>  172.x.251.54
- xxxxx-02  =>  172.x.238.55
- xxxxx-03  =>  172.x.251.56

Setelah itu saya seperti mendapat pencerahan, "owalahhh...." dan saya coba ubah skenarionya.

$ sudo strace -f ceph -s --debug-ms=99 -m 172.x.251.56
[...]
futex(Oxa745cc, FUTEX_WAKE_PRIVATE, 1) = 1
futex(Oxa74560, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x218db20, FUTEX_WAIT_BITSET_PRIVATE I FUTEX_CLOCK_REALTIME, O, NULL, Oxffffffff) = 0
futexCoxa745c8, FUTEX_WAIT_BITSET_PRIVATE I FUTEX_CLOCK_REALTIME, 0, {tv_sec=1642852349, tv_nsec=778854000}, Oxffffffff) = -1 EAGAIN (Resource temporarily unavailable)
futexCoxa74560, FUTEX_WAKE_PRIVATE, 1) = 0
futex(@x7ff4c0000e70, FUTEX_WAIT_BITSET_PRIVATE I FUTEX_CLOCK_REALTIME, 0, {tv_sec=3790335996, tv_nsec=773920000}, Oxffffffff) = 0
write(1, " cluster:\n id: 3938d835-"..., 862 cluster:
    id: xxxxx-xx-xxx-xxxx-xxxxxxx
    health: HEALTH_WARN
            no active mgr
            mons xxxxx-03, xxxxx-01 are using a lot of disk space
            1981 slow ops, oldest one blocked for 77 sec, daemons [mon.xxxxx-03, mon.xxxxx-01] have slow ops.
    services:
      mon: 2 daemons, quorum xxxxx-03, xxxxx-01 (age 19s)
      mgr: no daemons active (since 32h)
      osd: 836 osds: 826 up (since 15h), 816 in (since 15h); 154 remapped pgs
    data:
      pools:    10 pools, 12513 pgs
      objects:  346.45M objects, 1.3 PiB
      usage:    2.0 PiB used, 1.8 PiB / 3.8 PiB avail
      pgs:      12513 active+clean
    io:
      client:    13 MiB/s rd, 46 MiB/s wr, 813 op/s rd, 1.54k op/s wr
      cache:     32 MiB/s flush, 627 MiB/s evict, 52 op/s promote

)= 862
munmapC0x7ff4c459b000, 262144)
munmap(Øx7ff4c455b000, 262144)
munmap@x7ff4c44db000, 262144)
munmap(@x7ff4c465b000, 262144)
clone(child_stack=0x7ff4bf59dfbo, flags=CLONE_VMI CLONE_FS ICLONE_FILES I CLONE_SIGHAND I CLONE_THREAD I CLONE_SYSVSEMI CLONE_SETTLS I CLONE_PARENT_SETTIDICLONE_CHILD_CLEARTID, parent_tidptr=0x7ff4bf59e9do, tls=0x7ff4bf59e700, child_tidptr=0x7ff4bf59e9d0
- 490490
futexCoxa745cc, FUTEX_WAKE_PRIVATE, 1) = 1
futexCoxa74560, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x218db20, FUTEX_WAIT_BITSET_PRIVATE I FUTEX_CLOCK_REALTIME, O, NULL, Oxffffffff) = 0
[...]
+++ exited with 0 +++

Conclusion

Ternyata menurut kisah yang beredar, ceph-mon tersebut berubah segment IP dikarenakan pernah terjadi proses recreate ceph-mon menggunakan segment yang berbeda. Itu penyebab ketika saya kill ceph-mon pada host xxxxx-02, membuat ceph command stuck.

Untuk me-resolve hal tersebut hanya cukup mengubah config /etc/ceph/ceph.conf ke segment .251 (hal tersebut juga menyelesaikan masalah no active mgr), kemudian melakukan recreate ceph-mon, kembali ke .238. Baru setelah itu mengubah file konfigurasi seperti yang seharusnya.

Setelah Root Cause dari isu ini akhirnya selesai, *"saya akhirnya bisa melanjutkan malam minggu meskipun jatuhnya minggu-subuhan, bukan malam mingguan"*🥱.

Notes

Proses troubleshooting tidak semudah 5 langkah di atas, banyak sekali faktor/problem yang dalam prosesnya dilakukan. Namun tidak dituliskan. Tulisan di atas merupakan sebagian pendekatan yang saya lakukan sehingga bisa mengerucutkan proses troubleshooting.

"Everything will be fine if you just keep working on it, and take some cigarettes or coffee to meanwhile break also give a moment think clearly."

Reference

strace(1) - Linux manual page https://man7.org/linux/man-pages/man1/strace.1.html
Bug #14340: client command stuck forever - Ceph

https://ceph-users.ceph.narkive.com/xiTpiO1U/fwd-rbd-map-command-hangs

Troubleshooting Monitors - Ceph Documentation

https://docs.ceph.com/en/latest/rados/troubleshooting/troubleshooting-mon/

ceph: how to fix if monitor IP changes - 尚码园 https://www.shangmayuan.com/a/05cc4d6ab2e44b6cb71978d5.html