Diagnosa Bug Backend Librepods

Bug backend Librepods muncul ketika backend audio streaming gagal mengirim metadata terbaru ke klien saat terjadi sinkronisasi otomatis. Tujuan utama diagnostik adalah menjawab dua pertanyaan: apa gejalanya dan bagaimana reproduksi karakteristiknya. Dengan fokus pada repositori librepods-org/librepods, saya mengamati kegagalan HTTP 500 di endpoint /api/v1/stream/sync yang hanya muncul ketika dua permintaan sinkronisasi dibuat hampir bersamaan.

Pada log server, tanda awalnya adalah panic: send on closed channel pada goroutine streamSyncHandler. Log TRACE dari OpenTelemetry menunjukkan bahwa satu permintaan menutup channel event sebelum permintaan lain selesai membaca: pola ini menunjukkan race condition saat cache rekaman audio replikasi diperbarui.

Langkah diagnostik yang dilakukan:

  • Reproduksi: menggunakan skrip curl bersamaan dengan delay 20ms, memicu 500 error dan log panic.
  • Tracing: menambahkan span untuk fungsi streamSyncHandler dan syncMetadata agar terlihat jalur eksekusi.
  • Live log review: mengaktifkan logger.WithField("trace_id") untuk mengikuti event per request.

Dengan informasi ini, kita bisa pindah ke root cause.

Root Cause Analisis

Root cause terletak pada kombinasi channel internal yang ditutup secara agresif dan cache metadata yang tidak di-lock saat permintaan paralel. Dalam backend/audio/sync.go, handler menginisialisasi channel metadataReady chan struct{} dan menutupnya setelah sinkronisasi selesai. Namun, channel tersebut dibagikan antar permintaan karena disimpan di cache global syncCache.metadataReady tanpa perlindungan mutex.

Akibatnya, dua permintaan sinkronisasi yang berjalan hampir bersamaan akan saling berebut channel; satu goroutine menutup channel, goroutine lain yang masih menunggu event menerima panic send on closed channel. Situasi ini diperjelas oleh trace yang menunjukkan span syncMetadata menunggu channel lebih lama daripada yang diharapkan.

Root cause breakdown:

  1. Cache metadata tidak di-lock, sehingga channel dibagikan antar permintaan.
  2. Channel ditutup dari goroutine pertama sebelum goroutine kedua selesai menerima event.
  3. Handler tidak mengamankan akses jadi panic terjadi ketika goroutine kedua menulis ke channel yang sudah ditutup.

Perbaikan & Patch

Perbaikan dilakukan dengan dua pendekatan: menambahkan locking dan menggunakan objek yang berbeda per request. Berikut patch inti di backend/audio/sync.go:

type syncMetadataEntry struct {
    mu            sync.Mutex
    metadataReady chan struct{}
    metadata      *Metadata
}

func (e *syncMetadataEntry) ensureChannel() chan struct{} {
    e.mu.Lock()
    defer e.mu.Unlock()
    if e.metadataReady == nil {
        e.metadataReady = make(chan struct{})
    }
    return e.metadataReady
}

func streamSyncHandler(w http.ResponseWriter, r *http.Request) {
    entry := syncCache.getEntry(r.Context().UserID)
    ch := entry.ensureChannel()

    go func() {
        defer func() {
            entry.mu.Lock()
            close(ch)
            entry.metadataReady = nil
            entry.mu.Unlock()
        }()
        entry.syncMetadata(r.Context())
    }()

    select {
    case <-ch:
        writeResponse(w, entry.metadata)
    case <-r.Context().Done():
        http.Error(w, "timeout", http.StatusGatewayTimeout)
    }
}

Poin penting:

  • Setiap entry metadata punya mutex untuk menghindari race saat channel dibuat/ditutup.
  • Channel dibuat lazily per permintaan melalui ensureChannel, sehingga tidak ada goroutine yang langsung menutup channel yang digunakan goroutine lain.
  • Penutupan channel terjadi dalam defer goroutine yang melakukan sinkronisasi, sehingga tidak mempengaruhi goroutine lain.

Perlu juga menambahkan syncCache.mu saat mencatat entry agar tidak ada dua goroutine mengakses struct yang sama secara bersamaan.

Penerapan Observability & Verifikasi

Setelah patch selesai, langkah berikutnya adalah memastikan bug tidak kembali:

  • Observability tambahan: tambahkan log level INFO untuk lifecycle channel dan span events baru metadata.channel.created, metadata.channel.closed agar trace menunjukkan kapan channel dibuat.
  • Health check: tambahkan endpoint /health/sync-cache yang memastikan tidak ada entry stuck di channel terbuka lebih dari 30 detik.
  • Pengetesan: buat unit test yang membuat dua goroutine memanggil streamSyncHandler bersamaan, memverifikasi tidak terjadi panic dan kedua response berhasil.
  • Load test kecil: gunakan hey dengan -c 20 untuk mengirim request bersamaan ke endpoint sinkronisasi, mengamati tidak ada error 500.

Verifikasi manual di staging menyertakan log:

2024-10-10T10:10:10Z INFO sync: channel created user=1234 trace_id=abc123

2024-10-10T10:10:10Z INFO sync: channel closed user=1234 trace_id=abc123

Ini menunjukkan handler membuat dan menutup channel dengan rapi tanpa race.

Pelajaran & Best Practice Backend

Bug ini menggarisbawahi beberapa pelajaran untuk tim backend:

  1. Kelola shared state dengan mutex: setiap struktur cache yang diakses paralel harus punya proteksi eksplisit; rely tidak pada asumsi sequential.
  2. Jangan bagikan channel antar request kecuali channel immutable; lebih baik buat channel per request dengan locking untuk pembuatan/penutupan.
  3. Tracing & log kontekstual membantu menemukan race: menambahkan trace_id dan span per channel membedakan eksekusi overlapping.
  4. Test concurrency secara eksplisit: regression test harus meniru pola nyata; misalnya dua permintaan sinkronisasi paralel.
  5. Observability untuk lifecycle resource: logkan pembuatan/penutupan resource seperti channel dan track durasinya.

Dengan pendekatan ini, Librepods dapat memperbaiki bug sinkronisasi backend tanpa mengorbankan throughput atau stability.