strace ile uygulama davranışı inceleme

Merhaba değerli okuyucu. Bu yazı linux işletim sistemlerindeki uygulamaların işletim sistemine bulunduğu istekleri dinlemeye yarayan “strace” komutunun gerçek bir problemin tespitinde kullanılması hakkında olacak.

Şurada çok sevgili Gökhan Şengün yıllar yıllar önce bu konuda bir giriş yazısı yazmış ve devamı gelecek demişti. Malesef gelemedi :) Daha önce okumamış arkadaşlar için linkteki yazıyı okumalarını şiddetle öneriyorum. Bu yazı da kısmen devamı sayılsın.

Angaryos için teknoloji stakc ‘imizi güncellemek için major bir update planladık. Bu kapsamda da bir çok güncelleme gerçekleştirdik. Uygulamanın sunumu içinde Php 8.1 ile Swoole kullanmaya karar verdik. Swoole php uygulamalarının onlarca kat daha hızlı sunulmasını sağlayan akîlane bir uygulama.

Fakat bir sorun var. Güncellemede biraz yol alınca testleri koştururken bazen “408 time out” hatası almaya başladık. Sunucu loglarına baktığımda isteğin sunucu tarafından “200 success” olarak cevaplandığını görüyorum. En azında log o şelikde.

200    POST /api/v1/tables/columns .............. 31.60 mb 176.54 ms

Postman ise aynı isteğin 408 time out ile gerçekleştiğini söylüyor.

▶POST http:.../tables/columns............................ 408 234 ms

Önce Swoole yerleşik bir log kaydı tutuyor mu diye baktım. Biraz araştırmadan sonra aşağıdaki logu buldum. Swoole aynı anda çok fazla isteği yakalayabilmek için alt worker ‘lar ile birlikte çalışır. Sanırım bunlardan bir tanesinin (muhtemelen benim 408 aldığım requestimi karşılamış olan worker) 9 numaralı sinyal ile kapatıldığı yazıyordu.

İnternette kısa bir araştırma yaparsak bunun bir kill sinyali olduğunu görürüz. Yani benim worker ‘ımı birisi kill sinyali göndererek kapatıyordu. Aslında swoole ile alakalı “abnormal exit” hatasını araştırdım ama pek birşey bulamadım. Sonra daha derin bir inceleme yapmaya karar verdim. Önce tam olarak hangi process ‘in kapatıldığını tespit etmeye çalışıyorum. Bunun için “ps -aux” komutunu kullanıyorum.

Burada 4 tane process dikkatimi çekiyor muhtemelen bunlardan biri kapatılıyordur diyerek testleri çalıştırıp tekrar 408 hata kodunu alıp “ps -aux” ile hangi process ‘in yerinde durmadığını kontrol ediyorum ve gerçekten 1608 numaralı “swoole_http_server: worker process for Angaryos” process ‘inin kapatıldığını görüyorum. Bunun yanınında swoole ‘un log dosyasından da bu id ‘nin doğrulunu teyit ediyorum. Artık biliyoruz kapatılan process “worker”. Ama neden? Kim bunu hangi sebeple kapatıyor?

Aslında bunun çeşitli yöntemleri var ama biz bir docker container içinde çalıştığımız için elimiz biraz bağlı. Bunun için “strace” komutunu kullanmak istiyorum. Amacım bütün processleri strace ile izleyerek ilgili processim kapatıldığı anda izlemeyi kesmek ve logları geriye doğru takip etmek. Önce kimin kapattığını sonra neden kapattığını görmeyi amaçlıyorum.

İlk olarak aşağıdaki komut ile tüm process idlerini alıyorum. Çünkü tümünü izleyeceğim.

# ps -aux | awk -F ' ' '{print $2}' | tr '\n', ','

Bu bana “PID,1,9,12,54,55,65,73,757,1021,1954,2101,2111,2360,” çıktısını veriyor. Ardından aşağıdaki komut ile processlerin işletim sistemine yaptığı tüm cağrıları takip ederek bir log dosyası halinde kaydet diyorum. Aslında komuta ek olarak “-e trace=signal” parametresi ile yalnızca sinyal çağrılarını yakalayarak da processimi kimin öldürdüğünü bulabilirim ama ben belki başka bilgilerde alabilirim diye bu kısıtı koymuyorum.

# strace -p 1,9,12,54,55,65,73,757,1021,1954,2101,2111,2360 -o strace.log -tt

Ardından test setimi çalıştırıp Http 408 hatası aldırıyorum. Ve strace i durdurup log dosyamı incelemeye başlıyorum. Önce signal loglarını paylaşıyorum:

Bariz bir şekilde 54 di ‘li(swoole master)process 1608 numaralı processim için kill komutu gönderiyor. Ardından 65 id ‘li (swoole manager) process SIGCHLD yani alt processi kapatma çağrısı atıyor ama process daha önce öldüğü için bu çağrı bir işlem gerçekleştirmiyor. Yani katili bulduk. Ama bunu neden yapıyor? Sebebini araştırmak için daha önceki başka sistem çağrılarına da göz atmaya başlıyorum. Önce 408 hatasını 54 yani swoole master processin oluşturup döndüğünü görüyorum:

Zaten bulabildiğim tek şey de bu :) Bunun dışında alakalı başka hiçbir çağrı bulamadım. Manager uygulaması doğal sürecinde ilerlerken worker ‘ı kapatıyor. Bunun bir bug olduğunu düşünüyorum ve manager uygulaması seviyesinde hiçbir exception yok. Laravel seviyesinde de hiçbirşey olmamış gibi loglar normal akmaya devam ediyor.

Sonuç olarak strace ile uygulamaların işletim sistemi gözünden nasıl davrandığını inceleyip fikir sahibi olduk. Selametle kalın…