Geçenlerde memory-leak sebebiyle Production ortamında patlayan bir NodeJS process incelemesi yapmak zorunda kalmıştım, işte tavşan deliğine girişimin ve orada kayboluşumun hikayesi böyle başladı. Sanırım kendi dilimizde durumu daha iyi betimleyen bir ifade bulamadığım için İngilizcede kullanılan Rabbit Hole deyimi hep hoşuma gitmiştir.

Özellikle teknik konularda, problem çözmeye çalışırken ya da yeni bir konu, kavram öğrenirken, kendimi bazen bu deyimin ifade etmeye çalıştığı durum içinde buluyorum. Biraz da copy-paste yaklaşımı ile yüzeysel olarak geçiştirmeyi sevmeyen bir yapıda olduğumdan dolayı olabilir.

Bir konu öğrenirken, içinde geçen bilmediğim bir kavram varsa, “bunu bilmiyorum, bir bakayım neymiş”, diye baktıktan hemen sonra, bir bakmışım tavşan deliği beni bambaşka bir tarafa çıkarmış. Bu yeni konuyu incelerken de, bir bakmışım önümde bambaşka bir konu daha var ve kendimi ilk düşündüğümden, beklediğimden çok daha farklı konuları öğrenirken ya da incelerken bulmuşum. Kafamda hep bunun bir lanet mi yoksa hediye mi olduğu sorusu olsa da uzun vadede kontrol edebildiğiniz sürece, en azından kendi açımdan daha faydalı olduğunu gördüm diyebilirim.

Bu yazı serisi 3 bölümden oluşmaktadır, diğer bölümlere aşağıdaki linklerden ulaşılabilir. Yazı içeriğinde geçen kodlara bu adresten ulaşabilirsiniz.

Bölümler

  1. Sorunu Anlamak (Bu yazı)
  2. El İle Çözümleme
  3. Otomasyon

Sorunu Anlamak

  1. NodeJS Core Dump Problemi
  2. Stack Unwinding
  3. Sorun Derleyici Mi?
  4. Sorun Optimizasyonlar Mı?
  5. Sorun Debug Sembolleri Mi?
  6. LLDB Nasıl Çözümleme Yapabiliyor?
  7. İşin Sırrı EH Frame Tabanlı Çözüleme Mi?
  8. Musl .eh_frame Bilgisine Neden Sahip Değil?
  9. Neden GDB Çözümleme Yapamıyor?

NodeJS Core Dump Problemi

Tavşan deliğine inişimiz şöyle başladı, elimde NodeJS core dump dosyası var, bellek durumunu incelemek için, önce GDB ile problemin olduğu ortamda dosyayı yükleyip aşağıdaki gibi açtım. Kafamda en azından Call Stack beklentisi var. Onu görüp problemin oluştuğu yer ile ilgili daha net bir bilgi edinebilirim. Bunu GDB üzerinde yapabilmek için backtrace yani bt komutunu çalıştırdım ama aşağıda görüldüğü gibi libc içinde bulunan setjmp ve raise dışında NodeJS ile ilgili bir şey gözükmüyor, sadece ?? () maddeleri var.

/tmp # gdb /usr/local/bin/node -c core.f8f32091796c.node.1700129772.28 -q
Reading symbols from /usr/local/bin/node...
[New LWP 28]
[New LWP 30]
[New LWP 29]
[New LWP 33]
[New LWP 31]
[New LWP 32]
[New LWP 34]
Core was generated by `/usr/local/bin/node template.js'.
Program terminated with signal SIGABRT, Aborted.
#0  0x00007fa1a8f5a3f2 in setjmp () from /lib/ld-musl-x86_64.so.1
[Current thread is 1 (LWP 28)]
(gdb) bt
#0  0x00007fa1a8f5a3f2 in setjmp () from /lib/ld-musl-x86_64.so.1
#1  0x00007fa1a8f5a54d in raise () from /lib/ld-musl-x86_64.so.1
#2  0x00007fa1a8f5b9a9 in ?? () from /lib/ld-musl-x86_64.so.1
#3  0x00007fa1a8faae98 in ?? () from /lib/ld-musl-x86_64.so.1
#4  0x0000000000000000 in ?? ()
(gdb)

Sonuçta elimizdeki tek debugger GDB değil aynı dosyayı, bir de LLDB kurup onun üzerinden deneyip fark olacak mı diye görmek istedim. Aşağıdaki görüldüğü gibi LLDB herhangi bir sorun olmadan bana stack durumunu gösterebildi ve oradan da sorunun nerede olduğu anlaşabiliyor.

/tmp # lldb /usr/local/bin/node -c core.f8f32091796c.node.1700129772.28
(lldb) target create "/usr/local/bin/node" --core "core.f8f32091796c.node.1700129772.28"
Core file '/tmp/core.f8f32091796c.node.1700129772.28' (x86_64) was loaded.

(lldb) bt
* thread #1, name = 'node', stop reason = signal SIGABRT
  * frame #0: 0x00007fa1a8f5a3f2 ld-musl-x86_64.so.1`__setjmp + 109
    frame #1: 0x00007fa1a8f5a54d ld-musl-x86_64.so.1`raise + 55
    frame #2: 0x00007fa1a8f30f25 ld-musl-x86_64.so.1`abort + 14
    frame #3: 0x00005641a6ef5e55 node`node::Abort() + 37
    frame #4: 0x00005641a6e00d27 node`node::OnFatalError(char const*, char const*) + 283
    frame #5: 0x00005641a70ed0e2 node`v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) + 82
    frame #6: 0x00005641a70ed46f node`v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) + 847
    ...
    ...

Peki neden bu stack LLDB'de düzgün gözüküyor da, GDB'de düzgün gözükmüyor? diye sorduğum an tam olarak tavşan deliğine girmiş olduğum andı.

Stack Unwinding

Terminolojiyi öğrenince debugger araçları için bu Call Stack çıkarma işinin Stack Unwinding olarak adlandırıldığını öğrendim. Çoğu geliştirdiğimiz program, belleğe yüklendikten sonra, fonksiyon çağrılarını, lokal değişkenleri stack dediğimiz belleğin bir bölümü üzerinde gerçekleştiriyor. Kullandığımız IDE, Debugger vb.. araçlar ise stack durumunu analiz edip, bize şuanda bulunan duruma hangi fonksiyon çağrılarının yapılarak geldiğini, bu fonksiyon çağrıları içinde lokal değişkenleri ve değerlerini, CPU register değerlerini gösterebiliyor. Farkında olmasak da aslında debug yapıldığı her durumda genelde kullandığımız bir kavram.

Sorun Derleyici Mi?

Benim asıl merak ettiğim neden, bu işlemi, yani bu hataya hangi fonksiyon çağrılarını yaparak gelmiş bilgisini LLDB gösterebiliyorken GDB gösteremiyor. Bunu anlamak için kolları sıvayıp, önce bunun GDB ile ilgili bir bug olduğunu düşünüp en son versiyona geçirdim ama değişen bir şey olmadı. Ardından sorunun NodeJS ile ya da onu derlerken kullanılan compiler parametreleri ile olduğunu düşündüm. LLDB LLVM ailesinden olduğu için belki NodeJS clang ile derlendiyse üretilen dosyada aynı aileden olan LLDB üzerinden kolay debug edilebilmesi için ek semboller koyabilir diye düşündüm.

Tezimi, yani kullanılan derleyicinin stack analizine etkisini doğrulamak için aşağıdaki gibi çok basit bir C kodu yazıp, GCC ile derledim.

#include <stdio.h>
#include <stdlib.h>

int number=0;

int mul(int num, int times) {
  printf("Multiplying numbers: %d,%d\n", num, times);
  if (number > 10) {
    abort();
  }
  return num * times;
}

int sub(int num, int sub) {
  printf("Subtracting numbers: %d,%d\n", num, sub);
  int a = num - sub;
  int b = 2;
  return mul(a,b);
}

int add(int a, int b) {
    printf("Adding numbers: %d,%d\n", a, b);
    int c = a + b;
    int d = 5;
    return sub(c, d);
}

int main(int argc, char* argv[]) {
    number=atoi(argv[1]);
    printf("Number: %d\n", number);
    int result = add(3, 7);
    printf("Result: %d\n", result);
    return 0;
}

Yukarıdaki kodun amacı, birbirini çağıran birkaç fonksiyon kullanıp, ardından programı çağırırken verilen parametre değerine göre programın en son adımda hata alıp core-dump almasını sağlamak. Dump oluştuktan sonra GDB ile inceleme yapıp, Call Stack düzgün gözüküyor mu bunu inceleyeceğiz. Linux üzerinde dump almasını sağlayan belirli sinyalleri göndererek programın core-dump üretmesini sağlayabiliriz. Fakat programı çalıştırıp ardından kill ile tekrar sinyal göndermekten ise, program içinden bunu abort ile göndermeyi daha kolay bulduğum için mul fonksiyonu içinde rastgele bir değer seçip verilen parametre 10 değerinden büyük ise abort sinyali gönderip dump almasını sağladım.

Compiler olarak GCC kullanıyorum ve aşağıdaki gibi derledim. Production build işlemlerinde genelde optimizasyonlar açılır, ben de aynı şekilde optimizasyonu kullansın istedim ve ardından hata verdirecek parametre ile çağırdım, sonrasında da core dump dosyası oluştu.

/tmp # gcc -O2 main.c -o main
/tmp # ./main 15
Number: 15
Adding numbers: 3,7
Subtracting numbers: 10,5
Multiplying numbers: 5,2
Aborted (core dumped)

Programın kendini ve üretilen dump dosyasını parametre olarak GDB’ye geçerek, bir debug oturumu başlattım. Ardından backtrace komutunu çalıştırarak call stack görmek istedim, daha önce incelediğimiz NodeJS örneği ile benzer şekilde anlamlı fonksiyon isimleri yerine ?? işareti görüyoruz. Kısacası GDB stack unwinding işlemini yapamadı.

/tmp # gdb -q main -c core-main.1427.e28334d67f07.1705221934
Reading symbols from main...
[New LWP 1427]
Core was generated by `./main 15'.
Program terminated with signal SIGABRT, Aborted.
#0  0x00007f9e872e9d07 in setjmp () from /lib/ld-musl-x86_64.so.1
(gdb) bt
#0  0x00007f9e872e9d07 in setjmp () from /lib/ld-musl-x86_64.so.1
#1  0x00007f9e872e9e5c in raise () from /lib/ld-musl-x86_64.so.1
#2  0x0000003000000008 in ?? ()
#3  0x00007ffd0a120f00 in ?? ()
#4  0x00007ffd0a120e40 in ?? ()
#5  0x0000000000000000 in ?? ()

Yine aynı dosyayı ve dump dosyasını LLDB ile açtığımda ise aşağıdaki gibi düzgün olarak en azından anlamlı bir fonksiyon ismi add.cold görebiliyorum. Diğer fonksiyonlar optimizasyon sonucu compiler tarafından birleştirildi, o yüzden göremiyoruz ama buna rağmen bizim yazdığımız kodun bir parçası call stack içinde gözüküyor.

/tmp # lldb main -c core-main.1427.e28334d67f07.1705221934
(lldb) target create "main" --core "core-main.1427.e28334d67f07.1705221934"
Core file '/tmp/core-main.1427.e28334d67f07.1705221934' (x86_64) was loaded.
(lldb) bt
* thread #1, name = 'main', stop reason = signal SIGABRT
  * frame #0: 0x00007f9e872e9d07 ld-musl-x86_64.so.1`__setjmp + 118
    frame #1: 0x00007f9e872e9e5c ld-musl-x86_64.so.1`raise + 64
    frame #2: 0x00007f9e872bcfa8 ld-musl-x86_64.so.1`abort + 14
    frame #3: 0x000055752e9e908f main`add.cold + 5
    frame #4: 0x000055752e9e90c2 main`main + 50
    frame #5: 0x00007f9e872bcaad ld-musl-x86_64.so.1
(lldb)

Yani sorun compiler yani GCC ile alakalı değil, LLDB GCC ile derlenen bir programın dump dosyasını inceleyip optimizasyonlar açık olsa bile çıkarabildi fakat GDB aynı işlemi yapamadı.

Sorun Optimizasyonlar Mı?

Belki GDB’nin optimizasyonlar açık şekilde derlenmiş programların stack çözümlemesinde yaşadığı bir problem olabilir diye bu sefer optimizasyonları kapatıp o şekilde derleyip tekrar inceledim.

/tmp # gcc -Wall -O0 main.c -o main


/tmp # ./main 15
Number: 15
Adding numbers: 3,7
Subtracting numbers: 10,5
Multiplying numbers: 5,2
Aborted (core dumped)


/tmp # gdb -q main -c core-main.1464.e28334d67f07.1705226726
Reading symbols from main...
[New LWP 1464]
Core was generated by `./main 15'.
Program terminated with signal SIGABRT, Aborted.
#0  0x00007f4e291f0d07 in setjmp () from /lib/ld-musl-x86_64.so.1
(gdb) bt
#0  0x00007f4e291f0d07 in setjmp () from /lib/ld-musl-x86_64.so.1
#1  0x00007f4e291f0e5c in raise () from /lib/ld-musl-x86_64.so.1
#2  0x0000003000000008 in ?? ()
#3  0x00007ffcae6067e0 in ?? ()
#4  0x00007ffcae606720 in ?? ()
#5  0x00007ffcae606850 in ?? ()
#6  0x0000000000000005 in ?? ()
#7  0x0000000000000002 in ?? ()
#8  0x0000000000000000 in ?? ()

Aynı dump dosyasını LLDB ile incelediğimizde aşağıdaki gibi yine düzgün stack çözümlemesi yapabildiğini görüyoruz.

/tmp # lldb main -c core-main.1464.e28334d67f07.1705226726
(lldb) target create "main" --core "core-main.1464.e28334d67f07.1705226726"
Core file '/tmp/core-main.1464.e28334d67f07.1705226726' (x86_64) was loaded.
(lldb) bt
* thread #1, name = 'main', stop reason = signal SIGABRT
  * frame #0: 0x00007f4e291f0d07 ld-musl-x86_64.so.1`__setjmp + 118
    frame #1: 0x00007f4e291f0e5c ld-musl-x86_64.so.1`raise + 64
    frame #2: 0x00007f4e291c3fa8 ld-musl-x86_64.so.1`abort + 14
    frame #3: 0x0000561dda0701ff main`mul + 58
    frame #4: 0x0000561dda070251 main`sub + 73
    frame #5: 0x0000561dda07029e main`add + 75
    frame #6: 0x0000561dda0702f3 main`main + 83
    frame #7: 0x00007f4e291c3aad ld-musl-x86_64.so.1
(lldb)

Optimizasyonları kapatsak da işe yaramadı, GDB yine çözümleme işlemini yapamadı.

Sorun Debug Sembolleri Mi?

Bildiğiniz gibi çoğu derlenen programlama dilinde, debug ve release olarak iki farklı hedef bulunur. Özellikle geliştirme zamanında test ortamlarında hataların daha kolay incelenebilmesi için debug build kullanılır. Bunların içinde bulunan semboller ile aslında debugger bir nevi çalıştırılan makine/assembly komutlarının kod olarak hangi satıra denk geldiğini kolaylıkla bilir ve siz adım adım ilerlerken, sizin hangi satırda olduğunuzu değişken değerleri gibi şeyleri gösterebilir.

Belki GDB debug sembolleri olmadığı için, LLDB ise bu konuda özelliği olduğu için doğru analiz yapıyor olabilir, deneyip görelim.

/tmp # gcc -g -Wall -O0 main.c -o main

/tmp # ./main 15
Number: 15
Adding numbers: 3,7
Subtracting numbers: 10,5
Multiplying numbers: 5,2
Aborted (core dumped)

/tmp # gdb -q main -c core-main.1496.e28334d67f07.1705227527
Reading symbols from main...
[New LWP 1496]
Core was generated by `./main 15'.
Program terminated with signal SIGABRT, Aborted.
#0  0x00007f1f223f8d07 in setjmp () from /lib/ld-musl-x86_64.so.1
(gdb) bt
#0  0x00007f1f223f8d07 in setjmp () from /lib/ld-musl-x86_64.so.1
#1  0x00007f1f223f8e5c in raise () from /lib/ld-musl-x86_64.so.1
#2  0x0000003000000008 in ?? ()
#3  0x00007ffe75a26400 in ?? ()
#4  0x00007ffe75a26340 in ?? ()
#5  0x00007ffe75a26470 in ?? ()
#6  0x0000000000000005 in ?? ()
#7  0x0000000000000002 in ?? ()
#8  0x0000000000000000 in ?? ()

Görüldüğü gibi -g parametresi ile debug sembollerini de eklememize rağmen yine değişen bir şey olmadı. LLDB tarafında değişen bir şey yok, yine sorunsuzca stack çözümlemesini yapabiliyor o yüzden tekrar koymaya gerek duymadım.

Bu aşamada araştırma yaparken, problemin bizim kod ile alakalı değil de, stack çıktısının son adımında bulunan çağrılarda görüldüğü gibi kullanılan libc kütüphanesi yani musl-libc ile alakalı olabileceği aklıma geldi. Sonuçta program orada patlıyor ve debugger araçları çözümlemeyi oradan başlayarak yapmaya çalışıyor. Musl özellikle oldukça hafif ve optimize edilmesiyle bilinen bir kütüphane, içinde debug sembolleri olmasını beklemiyorum, ama bu tarz production ortamları için dağıttıkları debug sembolleri var mı diye kontrol ettim ve musl-dbg olarak ayrıca alpine deposunda bulunduğunu gördüm. Bunu paketi ekledikten sonra tekrar deneme yapalım.

/tmp # apk add musl-dbg
fetch https://dl-cdn.alpinelinux.org/alpine/v3.18/main/x86_64/APKINDEX.tar.gz
fetch https://dl-cdn.alpinelinux.org/alpine/v3.18/community/x86_64/APKINDEX.tar.gz
(1/1) Installing musl-dbg (1.2.4-r2)
OK: 545 MiB in 72 packages


/tmp # gdb -q main -c core-main.1496.e28334d67f07.1705227527
Reading symbols from main...
[New LWP 1496]
Core was generated by `./main 15'.
Program terminated with signal SIGABRT, Aborted.
#0  __restore_sigs (set=set@entry=0x7ffe75a26320) at ./arch/x86_64/syscall_arch.h:40
40      ./arch/x86_64/syscall_arch.h: No such file or directory.
(gdb) bt
#0  __restore_sigs (set=set@entry=0x7ffe75a26320) at ./arch/x86_64/syscall_arch.h:40
#1  0x00007f1f223f8e5c in raise (sig=sig@entry=6) at src/signal/raise.c:11
#2  0x00007f1f223cbfa8 in abort () at src/exit/abort.c:11
#3  0x000056227738f1ff in mul (num=5, times=2) at main.c:9
#4  0x000056227738f251 in sub (num=10, sub=5) at main.c:18
#5  0x000056227738f29e in add (a=3, b=7) at main.c:25
#6  0x000056227738f2f3 in main (argc=2, argv=0x7ffe75a264e8) at main.c:31

Harika sonunda ilerleme kaydedebildik, aslında sorunun asıl sebebi bizim programdan değilmiş. GDB debug sembolleri olmadığından musl kütüphanesinin stack çözümlemesini yapamıyor ve o yüzden bizim kodun da adımlarını gösteremiyor, musl debug sembollerini ekleyince sorun çözüldü.

LLDB Nasıl Çözümleme Yapabiliyor?

Musl debug sembollerini ekleyip sorunu çözdük deyip bıraksaydık işin eğlenceli kısmını, yani tavşan deliğinin derinliklerini keşfetme fırsatını kaçırırdık. Asıl eğlence bundan sonra başlıyor diyebiliriz.

Bu noktada LLDB’den biraz kopya çekmek istedim, en azından debug sembolleri olmadan bunu yapabildiğine göre ve işin içinde sihir olmadığına göre bir şekilde nasıl yaptığını öğrenip belki GDB’de aynı işi biz de yapabiliriz diye düşündüm. LLDB stack çözümleme işleminin nasıl yapıldığına dair logları isterseniz gösteriyor. Logları açıp tekrar aynı programı ve dump dosyasını yükledim sonuç aşağıdaki gibi oldu.

/tmp # lldb
(lldb) log enable lldb unwind
(lldb) target create main --core core-main.1496.e28334d67f07.1705227527
 (x86_64) /tmp/main: Reading EH frame info
 AssertFrameRecognizer::GetAbortLocation Unsupported OS
 AssertFrameRecognizer::GetAbortLocation Unsupported OS
 (x86_64) [vdso](0x00007ffe75b81000): Reading EH frame info
 (x86_64) /lib/ld-musl-x86_64.so.1: Reading EH frame info
 Process::SetPrivateState (stopped)
 Process::SetPrivateState (stopped) stop_id = 1
 th1/fr0 with pc value of 0x7f1f223f8d07, symbol name is '__setjmp'
 th1/fr0 0x00007f1f223f8c91: CFA=rsp +8 => rsp=CFA+0 rip=[CFA-8]
 th1/fr0 CFA is 0x7ffe75a26320: Register rsp (7) contents are 0x7ffe75a26318, offset is 8
 th1/fr0 initialized frame current pc is 0x7f1f223f8d07 cfa is 0x7ffe75a26320 afa is 0xffffffffffffffff using assembly insn profiling UnwindPlan
 th1/fr0 supplying caller's saved rip (16)'s location using assembly insn profiling UnwindPlan
 th1/fr0 supplying caller's register rip (16) from the stack, saved at CFA plus offset -8 [saved at 0x7ffe75a26318]
  th1/fr1 pc = 0x7f1f223f8e5c
 th1/fr0 supplying caller's register rbp (6) from the live RegisterContext at frame 0
  th1/fr1 fp = 0x7ffe75a26320
 th1/fr0 supplying caller's saved rsp (7)'s location using assembly insn profiling UnwindPlan
 th1/fr0 supplying caller's register rsp (7), value is CFA plus offset 0 [value is 0x7ffe75a26320]
  th1/fr1 sp = 0x7ffe75a26320
  th1/fr1 with pc value of 0x7f1f223f8e5c, symbol name is 'raise'
  th1/fr1 Backing up the pc value of 0x7f1f223f8e5c by 1 and re-doing symbol lookup; old symbol was raise
  th1/fr1 Symbol is now raise
  th1/fr1 Using full unwind plan 'assembly insn profiling'
  th1/fr1 active row: 0x00007f1f223f8e2a: CFA=rbp+160 => rbx=[CFA-24] rbp=[CFA-16] rsp=CFA+0 rip=[CFA-8]
  ...
  ...
  ...

Burada dikkatimi çeken ilk şey yukarıdaki loglarda geçen aşağıdaki satırlar oldu.

 ...
 (x86_64) /lib/ld-musl-x86_64.so.1: Reading EH frame info
 ...
 ...
 th1/fr0 initialized frame current pc is 0x7f1f223f8d07 cfa is 0x7ffe75a26320 afa is 0xffffffffffffffff using assembly insn profiling UnwindPlan
 ...

İşin Sırrı EH Frame Tabanlı Çözüleme Mi?

Yukarıdaki loglarda görüldüğü gibi LLDB çözümleme yaparken ilk olarak EH frame bilgisini okumuş ardından assembly insn profiling UnwindPlan kullanıyorum demiş. EH Frame daha önce duymadığım bir kavram olduğu için, tavşan deliğinden yeni bir tünele doğru yola çıkmış olduk.

EH Frame yani Exception Handling Frame C++ programlama dilinde exception oluşması durumunda hataya gelene kadar tüm stack üzerinde bulunan tüm çağrı bilgilerinin çözümlenmesini kolaylaştırmak için DWARF debug sembol standartının bir parçası olarak geliştirilmiş. Kendisi, debug sembollerinin tutulduğu kısımda tutulmuyor, belirli bir tarihten beri derleyiciler siz aksini belirtmedikçe varsayılan olarak bu bilgiyi derlenen binary içerisine gömüyorlar. Amaç hata olduğunda ya da debug işlemi sırasında stack çözümlemeyi kolaylaştırmak. İşin güzel tarafı bu bilgi C programları için de aynı şekilde tutuluyor.

LLDB bu bilgiyi mi kullanıyor diye anlamak için önce, kullanılan musl-libc kütüphanesinin .eh_frame bilgisine bakalım.

/tmp # readelf --debug-dump=frames-interp  /lib/ld-musl-x86_64.so.1
Contents of the .eh_frame section:


00000000 0000000000000014 00000000 CIE "zR" cf=1 df=-8 ra=16
   LOC           CFA      ra
0000000000000000 rsp+8    c-8

00000018 0000000000000024 0000001c FDE cie=00000000 pc=0000000000014000..0000000000014070
   LOC           CFA      ra
0000000000014000 rsp+16   c-8
0000000000014006 rsp+24   c-8
0000000000014010 exp      c-8

00000040 0000000000000014 00000044 FDE cie=00000000 pc=00000000000140a0..000000000001432c

00000058 0000000000000014 0000005c FDE cie=00000000 pc=0000000000014330..00000000000145ed

00000070 0000000000000010 00000074 FDE cie=00000000 pc=00000000000145f0..00000000000149ee

Çıkan bilginin nasıl yorumlanacağına dair daha detaylı bilgileri referanslar kısmında bulabilirsiniz, fakat özetlemek gerekirse bize pc yani program counter adresinin bulunduğu yere göre stack frame adresinin nerede bulunduğunu gösteren bir tablo oluşturmamıza olanak veriyor. Örnek olarak aşağıdaki kısmını değerlendirelim

00000018 0000000000000024 0000001c FDE cie=00000000 pc=0000000000014000..0000000000014070
   LOC           CFA      ra
0000000000014000 rsp+16   c-8
0000000000014006 rsp+24   c-8
0000000000014010 exp      c-8

PC değeri 14000 ile 14070 arasında ise 14000 için CFA yani stack frame değeri, rsp+16 adresinde bulunur, ra yani return address değeri ise CFA-8 adresinde bulunur gibi bilgiler vererek bu işi kolaylaştırıyor, stack çözümleme işlemi yaparken de bu tablo ile Call Stack kolaylıkla çıkarılabiliyor.

Peki musl-libc içinde bizim hata aldığımız yani setjmp ya da raise gibi fonksiyonlar bu tabloya dahil mi?

/tmp # objdump -S -Mintel /lib/ld-musl-x86_64.so.1

Yukarıdaki gibi disassemble ederek çıkan adresleri incelediğimde bizim hata aldığımız son iki fonksiyonun adreslerini aşağıdaki gibi görüyorum.

0000000000048c91 <__setjmp>:
   48c91:       48 89 1f                mov    QWORD PTR [rdi],rbx
   48c94:       48 89 6f 08             mov    QWORD PTR [rdi+0x8],rbp
   48c98:       4c 89 67 10             mov    QWORD PTR [rdi+0x10],r12
   48c9c:       4c 89 6f 18             mov    QWORD PTR [rdi+0x18],r13
   ...
   ...
0000000000048e1c <raise>:
   48e1c:       55                      push   rbp
   48e1d:       53                      push   rbx
   48e1e:       89 fb                   mov    ebx,edi
   48e20:       48 81 ec 88 00 00 00    sub    rsp,0x88
   48e27:       48 89 e5                mov    rbp,rsp
   ...
   ...

Yukarıdaki adres bilgilerine (48c91,48e1c) bakacak olursanız, bizim elimizde olan 14000-14070 aralığında değiller. Buraya kadar oldukça umudum vardı, artık bu sorunun burada .eh_frame tablosundaki bilgiler ile çözülebileceğini düşünmüştüm ama maalesef, tavşan deliğinde önümüze çıkacak yeni tüneller var.

Yine de yukarıdaki .eh_frame tablosunda neler var bakmak istedim, neden plt yani Procedure Linkage Table var hala emin değilim.

Disassembly of section .plt:

0000000000014000 <malloc@plt-0x10>:
   14000:       ff 35 2a 2f 08 00       push   QWORD PTR [rip+0x82f2a]        # 96f30 <stdout+0x1d8>
   14006:       ff 25 2c 2f 08 00       jmp    QWORD PTR [rip+0x82f2c]        # 96f38 <stdout+0x1e0>
   1400c:       0f 1f 40 00             nop    DWORD PTR [rax+0x0]

0000000000014010 <malloc@plt>:
   14010:       ff 25 2a 2f 08 00       jmp    QWORD PTR [rip+0x82f2a]        # 96f40 <malloc+0x71cb1>
   14016:       68 00 00 00 00          push   0x0
   1401b:       e9 e0 ff ff ff          jmp    14000 <malloc@plt-0x10>
   ...
   ...

Neden musl-libc içinde sadece plt kısmı ile ilgili bilgiler varken diğer kısımlar ile ilgili .eh_frame bilgisi yok diye araştırırken Musl mail listesinde bu konuya denk geldim orada, sebep aşağıdaki gibi gözüküyor

Accordingly, I would strongly prefer that Alpine try to solve this issue with .debug_frame first, and then we can look at .eh_frame later if it winds up being insufficient for making basic debug functionality work (on at least the same level as glibc).

Konu içinde yazılmalara bakacak olursanız, backtrace senaryosu için .eh_frame bilgisinin içine konulmasını istemişler ama geliştiriciler eğer debug yapmak istiyorsan musl-dbg paketini yükle orada debug sembolleri var onunla işini hallet demişler özetle.

İki tarafı da bir noktaya kadar anlayabiliyorum, geliştiriciler çözüm sunmuş, aslında .eh_frame çalışma zamanında herhangi bir performans etkisi olmasa da, dağıtılan binary boyutu belirli bir oranda büyüyor. Musl gibi gömülü ortamlarda çalışan, hatta Alpine standart C kütüphanesi olarak seçilmesinin de en büyük sebebi güvenlik ve kompak oluşu, bundan dolayı eklememek onların açısından doğru.

Fakat kendi açımdan tamamen offline bir ortamda musl-dbg paketini kuramadığım durumlar olduğu ve çok küçük bir boyut artışının bana ve çalıştığım projelere zararı olmadığı için bu bilgi çıkarılmadan dağıtılması işime gelirdi.

Musl .eh_frame Bilgisine Neden Sahip Değil?

Daha önce demiştik, derleyici herhangi bir ek parametre kullanmazsanız .eh_frame bilgisini otomatik olarak dahil ediyor. Peki bu tarz uç durumlarda biz bunu nasıl çıkarabiliriz, ya da Musl nasıl dahil etmemiş. Aslında derleyici bunları dahil etmek istemezseniz size yine seçenek sunuyor. Aşağıdaki parametreleri kullandığınızda .eh_frame olmadan çıktığını görebilirsiniz.

/tmp # gcc -fomit-frame-pointer -fno-exceptions -fno-asynchronous-unwind-tables -fno-unwind-tables -Wall -O0 main.c -o main2


/tmp # readelf --debug-dump=frames-interp  main2
Contents of the .eh_frame section:

00000000 ZERO terminator

Contents of the .debug_frame section:

00000000 0000000000000014 ffffffff CIE "" cf=1 df=-8 ra=16
   LOC           CFA      ra
0000000000000000 rsp+8    c-8

00000018 0000000000000014 00000000 FDE cie=00000000 pc=0000000000001096..00000000000010b9

/tmp # objdump -S -Mintel main2 | sed -n '/1096/,/10b9/p'
    1091:       e8 00 00 00 00          call   1096 <_start_c>

0000000000001096 <_start_c>:
    1096:       8b 37                   mov    esi,DWORD PTR [rdi]
    1098:       48 8d 57 08             lea    rdx,[rdi+0x8]
    109c:       4c 8d 05 8c 02 00 00    lea    r8,[rip+0x28c]        # 132f <_fini>
    10a3:       45 31 c9                xor    r9d,r9d
    10a6:       48 8d 0d 53 ff ff ff    lea    rcx,[rip+0xffffffffffffff53]        # 1000 <_init>
    10ad:       48 8d 3d 03 02 00 00    lea    rdi,[rip+0x203]        # 12b7 <main>
    10b4:       e9 97 ff ff ff          jmp    1050 <__libc_start_main@plt>
    10b9:       0f 1f 80 00 00 00 00    nop    DWORD PTR [rax+0x0]

Aynı kodu yukarıdaki gibi derlediğimde .eh_frame bilgisi sanırım programın başlaması için gerekli olan _start_c kısmı için konulmuş. Diğer tüm kısımlarla ilgili bu bilgi kaldırılmış.

Sonuç olarak LLDB çözümlemeyi nasıl yapmış diye bakacak olursak, ilgili kısımlar için .eh_frame bilgisi olmadığına göre, işin sırrı using assembly insn profiling UnwindPlan satırında gizli diye düşünüyorum.

Neden GDB Çözümleme Yapamıyor?

Biraz da LLDB tarafından GDB tarafına geçip logları inceleyelim, orada neden çözümleme yapamadığına dair ipucu bulabiliriz. GDB ile aynı çalıştırılabilir dosyayı tekrar açtım. Oldukça fazla log üretiyor, çoğunu kırptım önemli olanlarını bıraktım. Stack çözümleme loglarını açmak için set debug frame on komutunu kullanıyoruz.

/tmp # gdb -q main -c core-main.1496.e28334d67f07.1705227527
Reading symbols from main...

warning: exec file is newer than core file.
[New LWP 1496]
Core was generated by `./main 15'.
Program terminated with signal SIGABRT, Aborted.
#0  0x00007f1f223f8d07 in setjmp () from /lib/ld-musl-x86_64.so.1
(gdb) set debug frame on
[frame] get_prev_frame_always_1: enter
  [frame] get_prev_frame_always_1: this_frame=-1
  [frame] get_prev_frame_always_1:   -> {level=0,type=NORMAL_FRAME,unwinder="amd64 epilogue",pc=0x7f1f223f8d07,id=<not computed>,func=<unknown>} // cached
[frame] get_prev_frame_always_1: exit
...
...
    [frame] compute_frame_id: enter
      [frame] compute_frame_id: fi=1
      [frame] frame_unwind_find_by_frame: enter
        [frame] frame_unwind_find_by_frame: this_frame=1
        [frame] frame_unwind_arch: next_frame=0 -> i386:x86-64
        [frame] frame_unwind_try_unwinder: trying unwinder "dummy"
        [frame] frame_unwind_try_unwinder: no
        [frame] frame_unwind_try_unwinder: trying unwinder "dwarf2 tailcall"
        [frame] frame_unwind_try_unwinder: no
        [frame] frame_unwind_try_unwinder: trying unwinder "inline"
        [frame] frame_unwind_register_value: enter
          [frame] frame_unwind_register_value: frame=0, regnum=16(rip)
          [frame] frame_unwind_register_value:   -> address=0x7ffe75a26318 lazy
        [frame] frame_unwind_register_value: exit
        [frame] frame_unwind_pc: this_frame=0 -> 0x7f1f223f8e5c
        [frame] frame_unwind_try_unwinder: no
        [frame] frame_unwind_try_unwinder: trying unwinder "jit"
        [frame] frame_unwind_try_unwinder: no
        [frame] frame_unwind_try_unwinder: trying unwinder "python"
        [frame] frame_unwind_try_unwinder: no
        [frame] frame_unwind_try_unwinder: trying unwinder "amd64 epilogue"
        [frame] frame_unwind_try_unwinder: no
        [frame] frame_unwind_try_unwinder: trying unwinder "i386 epilogue"
        [frame] frame_unwind_try_unwinder: no
        [frame] frame_unwind_try_unwinder: trying unwinder "dwarf2"
        [frame] frame_unwind_try_unwinder: no
        [frame] frame_unwind_try_unwinder: trying unwinder "dwarf2 signal"
        [frame] frame_unwind_try_unwinder: no
        [frame] frame_unwind_try_unwinder: trying unwinder "amd64 sigtramp"
        [frame] frame_unwind_try_unwinder: no
        [frame] frame_unwind_try_unwinder: trying unwinder "amd64 prologue"
        [frame] frame_unwind_try_unwinder: yes
      [frame] frame_unwind_find_by_frame: exit
      ...
      ...

Önemli ilk log type=NORMAL_FRAME,unwinder="amd64 epilogue" bu satır diye düşünüyorum. GDB ilk stack frame bilgisinin yani setjmp kısmında kalan stack çağrısının normal bir frame olduğunu düşünüyor ve amd64 epilogue ile çözebileceğini sanıyor. Onun altında ise daha başka hangi stack çözümleme yöntemlerini kullanıyor ve sonuçları ne olmuş yazmış.

trying unwinder "dummy"
trying unwinder "dwarf2 tailcall"
trying unwinder "inline"
trying unwinder "jit"
trying unwinder "python"
trying unwinder "amd64 epilogue"
trying unwinder "i386 epilogue"
trying unwinder "dwarf2"
trying unwinder "dwarf2 signal"
trying unwinder "amd64 sigtramp"
trying unwinder "amd64 prologue"

Yukarıda listeden de görebileceğiniz gibi, elimizde musl-libc için denenmiş çözümleme yöntemleri gözüküyor. Listede dwarf2 ile ilgili olan maddeler elimizde musl-libc debug sembolleri olmadığı için işe yaramıyor, diğerleri de direk derlediğimiz kodla alakalı değil, GDB’nin en mantıklı bulduğu ve seçtiği amd64 epilogue tabanlı çözümleme yöntemi ise işe yaramıyor.

Buraya kadar GDB’nin neden düzgün analiz yapamayıp LLDB’nin yapabildiğini anladık diye düşünüyorum. LLDB yukarıda bahsettiğim gibi assembly kodlarına bakarak bir çözümleme planı oluşturuyor ve başarılı şekilde bize stack çağrılarını çıkarıyor. Yukarıda GDB’nin denediği maddeler arasında böyle bir çözümleme yöntemi yok ya da hata aldığı setjmp fonksiyonu, GDB tarafından yanlış yorumlanıyor, bundan dolayı ?? işaretlerini görüyoruz.

Bir sonraki bölümde bu sorunu nasıl GDB’ye yardımcı olarak giderebiliriz, kolları sıvayıp işe koyulacağız.

Referanslar

<
Previous Post
Sorun Her Zaman DNS - Musl LibC
>
Next Post
Core Dump Stack Analizi 2 - El İle Çözümleme