Gw pernah nemuin issue agak aneh di salah satu service yang gw handle. Service ini perlu download sebuah asset dari internet sebelum lanjut ke proses berikutnya, tapi request download-nya selalu timeout. Karena file-nya kecil, awalnya gw mikir mungkin server tempat file-nya disimpan lagi lambat atau koneksi di mesin tersebut memang lagi jelek.

Gw coba masuk ke container dan download file yang sama secara manual pake wget:

time wget https://assets.example.com/file.png

File-nya berhasil didownload, tapi ada yang aneh dari waktunya:

file.png  100%  477 KB/s

real    0m9.556s
user    0m0.036s
sys     0m0.016s

Kecepatan download-nya normal dan proses transfer file-nya sendiri gak sampai satu detik, tapi totalnya hampir sepuluh detik. Jadi sekitar sembilan detik sisanya dipake buat apa?

Coba lihat pake strace

Jujur gw sendiri belum terlalu paham pake strace. Gw cuma tau tool ini bisa dipake buat melihat interaksi antara sebuah process dengan kernel, termasuk syscall dan signal yang diterima process tersebut. Output-nya juga banyak banget dan kebanyakan gak gw ngerti, tapi karena dari log aplikasi gak ada informasi apa-apa akhirnya gw coba aja.

Gw jalanin wget lagi, kali ini lewat strace. Opsi -r dipake supaya kelihatan berapa lama jarak dari satu syscall ke syscall berikutnya.

strace -r wget https://assets.example.com/file.png

Setelah nyari bagian yang kelihatan berhenti lama, gw nemuin potongan ini:

0.000082 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 3
0.000088 connect(3, {sa_family=AF_INET, sin_port=htons(53), ...}, 16) = 0
0.000080 sendmmsg(3, [...], 2, MSG_NOSIGNAL) = 2
0.000230 poll([{fd=3, events=POLLIN}], 1, 5000) = 0 (Timeout)
5.005576 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 4

Sebelum wget bisa membuat HTTPS connection, dia perlu mengubah domain assets.example.com menjadi IP address dulu. Resolver membaca daftar DNS dari /etc/resolv.conf, membuat UDP socket ke port 53, lalu mengirim query untuk menanyakan IP dari domain tersebut.

Di log ini, connect() yang return 0 bukan berarti DNS-nya sudah berhasil. Karena ini UDP, gak ada handshake seperti TCP. connect() cuma menentukan ke mana datagram akan dikirim. Setelah query dikirim lewat sendmmsg(), resolver memanggil poll() untuk menunggu ada data balasan di socket tersebut. Argument 5000 artinya dia bersedia nunggu sampai lima detik, dan hasil 0 (Timeout) berarti gak ada satu pun jawaban yang masuk selama waktu itu.

Setelah gagal, resolver baru mencoba DNS berikutnya dan download bisa lanjut. Sedangkan timeout di aplikasi cuma tiga detik, jadi aplikasinya udah keburu nyerah bahkan sebelum percobaan ke DNS pertama selesai.

DNS host dan container ternyata beda

Gw lalu bandingin /etc/resolv.conf di dalam container dengan hasil resolvectl status di host. Kira-kira kondisinya seperti ini, IP-nya tentu sudah gw samarkan:

DNS Servers:        192.0.2.53 203.0.113.53
Current DNS Server: 203.0.113.53

Ada dua DNS server yang didapat mesin dari network interface. DNS pertama udah gak membalas, sedangkan yang kedua masih hidup. Resolver di host sudah sadar DNS pertama bermasalah dan Current DNS Server-nya sudah pindah ke DNS kedua, makanya request yang dijalankan langsung dari host tetap normal.

Masalahnya, di setup ini /etc/resolv.conf milik container masih berisi daftar upstream DNS tersebut dan DNS yang mati tetap berada di urutan pertama:

nameserver 192.0.2.53
nameserver 203.0.113.53

Container punya network namespace sendiri, jadi dia gak otomatis ikut state resolver di host yang sudah memilih DNS kedua. Resolver di dalam container membaca daftar tadi dari awal dan tetap mencoba 192.0.2.53 terlebih dahulu. Baru setelah poll() timeout dia pindah ke 203.0.113.53.

Pas DNS pertama gw query langsung pake dig, hasilnya juga timeout. Jadi bukan domain tujuan yang gagal di-resolve, urutan DNS di container aja yang membuat setiap lookup harus melewati server mati terlebih dulu. Pantes request-nya selalu telat walaupun koneksi dan kecepatan download sebenarnya normal.

Untuk ngebuktiin masalahnya memang ada di network container, gw coba jalanin container pake host network:

docker run --network host ...

Setelah pake host network, strace menunjukkan DNS query-nya gak lagi dikirim langsung ke DNS yang mati, tapi ke 127.0.0.53, yaitu stub resolver milik systemd-resolved di host. Karena container sekarang berbagi network namespace dengan host, alamat loopback tersebut mengarah ke resolver host yang sudah memakai DNS kedua. Request yang sebelumnya hampir sepuluh detik akhirnya selesai kurang dari satu detik.

Host network akhirnya dipake sebagai workaround paling cepat waktu itu, tapi menurut gw ini bukan fix yang paling bersih karena container jadi berbagi network stack dengan host dan isolation-nya berkurang. Fix yang lebih bener harusnya memperbaiki DNS dari DHCP atau router, atau set DNS yang memang hidup lewat konfigurasi Docker maupun opsi --dns.

Di sisi aplikasi gw juga menambahkan caching supaya asset yang sama gak perlu didownload terus-terusan. Ini gak memperbaiki DNS-nya, tapi setidaknya aplikasi gak selalu bergantung ke network setiap kali prosesnya jalan.

Sebelumnya kalau nemu HTTP request timeout gw biasanya langsung curiga ke server tujuan atau koneksi internet. Gak kepikiran kalau sebagian besar waktunya malah habis sebelum HTTP request-nya dimulai. Untungnya walaupun output strace kelihatan menyeramkan, kadang kita gak perlu ngerti semuanya. Cukup cari satu baris yang nunggu lima detik dan mulai ngulik dari sana.