Telemetry dan logging

Aplikasi yang mampu pulih secara otomatis tetap membutuhkan pengamatan, karena supervisor hanya menjamin process hidup kembali, bukan menjamin peristiwanya tercatat. Topik ini membahas dua perkakas pengamatan pada ekosistem Elixir, yaitu Telemetry untuk pelaporan peristiwa terstruktur dan Logger untuk pencatatan log. Pembahasannya mencakup cara memancarkan event beserta pengukurannya, menyaring pesan menurut level, dan melampirkan metadata pada log. Setelah topik ini dibaca, peristiwa aplikasi dapat dilaporkan, disaring, dan diolah sebagai data.

Event Telemetry#

Telemetry adalah pustaka instrumentasi yang menjadi standar pelaporan peristiwa (event) pada ekosistem BEAM, digunakan antara lain oleh Phoenix dan Ecto untuk melaporkan siklus permintaan dan kueri. Peristiwa dinamai dengan daftar atom seperti [:aplikasi, :kirim], dan pemancar tidak perlu mengetahui pemrosesnya. Pemroses memasang handler, yaitu fungsi yang dipanggil untuk setiap event dengan nama yang cocok. Hubungan keduanya dibangun melalui :telemetry.attach/4 yang diberi pengenal unik. Pengenal yang sama digunakan untuk melepas handler melalui :telemetry.detach/1, sedangkan pemancar menjalankan :telemetry.execute/3.

Skrip berikut memasang satu handler pada event [:aplikasi, :kirim], lalu memancarkan event yang sama dua kali, pertama dengan metadata dan kedua tanpa metadata:

Mix.install([{:telemetry, "~> 1.2"}])
Logger.configure(level: :warning)

defmodule Pengamat do
  # handler Telemetry: menerima event, pengukuran, dan metadata
  def tangani(event, pengukuran, metadata, _konfigurasi) do
    IO.puts("event diterima: #{inspect(event)}")
    IO.inspect(pengukuran, label: "pengukuran")
    IO.inspect(metadata, label: "metadata")
    :ok
  end
end

# memasang pengamat pada event [:aplikasi, :kirim]
:ok = :telemetry.attach("pengamat-kirim", [:aplikasi, :kirim], &Pengamat.tangani/4, nil)

# memancarkan event dengan pengukuran dan metadata
:telemetry.execute([:aplikasi, :kirim], %{durasi_ms: 120}, %{tujuan: "arsip", ukuran_kb: 24})

# memancarkan event tanpa metadata
:telemetry.execute([:aplikasi, :kirim], %{durasi_ms: 512})

event diterima: [:aplikasi, :kirim]
pengukuran: %{durasi_ms: 120}
metadata: %{tujuan: "arsip", ukuran_kb: 24}
event diterima: [:aplikasi, :kirim]
pengukuran: %{durasi_ms: 512}
metadata: %{}

Keluaran menunjukkan handler terpanggil dua kali dengan isi yang sesuai pemancarnya. Panggilan pertama membawa pengukuran durasi_ms beserta metadata tujuan dan ukuran berkas, sedangkan panggilan kedua dibiarkan tanpa metadata sehingga handler menerimanya sebagai map kosong. Seluruh pemanggilan berlangsung di dalam process yang sama dengan pemancarnya, sebab :telemetry.execute/3 memanggil setiap handler secara langsung tanpa process perantara.

Pengukuran dan metadata#

telemetry.execute/3 membagi isi event menjadi dua bagian yang sengaja dipisahkan, yaitu pengukuran (measurement) dan metadata. Pemisahan ini bukan sekadar kebiasaan, melainkan kontrak yang membuat event dapat diagregasi secara seragam oleh pustaka pengolahnya:

Pengukuran hanya berisi angka, sehingga pustaka agregasi seperti Telemetry.Metrics dapat menghitung rata-rata durasi tanpa menafsirkan maknanya. Sebaliknya, metadata bebas berisi data apa pun, dan tugasnya menemani pengukuran dengan konteks yang tidak dihitung. Konvensi penamaan ekosistem menempatkan nama penerbitnya di awal daftar, sehingga event bawaan Ecto berupa [:ecto, :repo, :query] dan event Phoenix berupa [:phoenix, :endpoint, :start]. Satu event dapat dipasangi lebih dari satu handler, sehingga pencatatan log dan pengumpulan metrik berjalan berdampingan tanpa saling menunggu.

Level log pada Logger#

Logger adalah modul logging bawaan Elixir yang mencatat pesan berlevel. Urutan level dari yang paling terperinci adalah :debug, :info, :warning, dan :error, dan pesan yang levelnya berada di bawah ambang dibuang sebelum sempat dicetak. Pengaturannya dilakukan melalui Logger.configure/1, misalnya Logger.configure(level: :warning) yang hanya meloloskan pesan berlevel peringatan ke atas.

Cara membuktikan penyaringan level adalah menjalankan pesan uji, lalu memeriksa apakah pesan itu lolos. Modul ExUnit.CaptureLog menyediakan capture_log/2 yang menjalankan sebuah fungsi dan mengembalikan seluruh teks log yang terbit selama fungsi itu berjalan. Perekam ini tidak mengubah level Logger yang berlaku, sehingga perilaku penyaringannya tetap asli. Skrip memerlukan ExUnit.start/1 di awal karena aplikasi :ex_unit belum berjalan pada skrip biasa, dan macro Logger memerlukan require Logger:

ExUnit.start(autorun: false)
require Logger
Logger.configure(level: :warning)

info_terekam =
  ExUnit.CaptureLog.capture_log(fn -> Logger.info("pesan info") end)
  |> String.contains?("pesan info")

peringatan_terekam =
  ExUnit.CaptureLog.capture_log(fn -> Logger.warning("peringatan penting") end)
  |> String.contains?("peringatan penting")

IO.inspect(info_terekam, label: "info terekam")
IO.inspect(peringatan_terekam, label: "peringatan terekam")

info terekam: false
peringatan terekam: true

Keluaran menegaskan perilaku level :warning. Pesan Logger.info/1 tidak terekam karena levelnya berada di bawah ambang, sedangkan Logger.warning/1 terekam utuh. Pola semacam ini layak digunakan pada pengujian, karena yang diuji adalah isi pesannya dan bukan bentuk barisnya.

Log terstruktur dengan metadata#

Logger menyimpan metadata, yaitu data konteks yang melekat pada process pemanggil dan bukan bagian dari teks pesannya. Fungsi Logger.metadata/1 menambahkan atau mengubah metadata process saat ini, dan Logger.metadata/0 membacanya kembali. Karena penyimpanannya per process, process lain memiliki metadata miliknya masing-masing. Formatter log dapat dikonfigurasi untuk mencantumkan metadata tertentu pada setiap baris yang diterbitkan.

Bentuk log terstruktur paling mudah diamati apabila entri diperlakukan sebagai data, bukan kalimat bebas. Map berikut menggambarkan satu entri yang lengkap beserta metadata processnya. Karena map tidak menjamin urutan kuncinya, pasangan kunci dan nilainya diurutkan lebih dahulu sebelum dicetak:

require Logger

Logger.metadata(loket: 3, antrean: "A")
IO.inspect(Logger.metadata(), label: "metadata process ini")

entri = %{
  level: :info,
  pesan: "tiket dilayani",
  loket: 3,
  nomor_tiket: 42
}

IO.inspect(Enum.sort(Map.to_list(entri)), label: "entri log terstruktur")

metadata process ini: [loket: 3, antrean: "A"]
entri log terstruktur: [level: :info, loket: 3, nomor_tiket: 42, pesan: "tiket dilayani"]

Entri berbentuk data seperti di atas memudahkan pengolahan lanjutan, misalnya menyaring seluruh entri dari loket tertentu atau menghitung jumlah tiket yang dilayani. Hal itu mungkin karena seluruh nilainya berupa data yang dapat dicocokkan tanpa mengurai teks bebas. Metadata Logger berperan pada sisi penerbitannya, yaitu melengkapi setiap pesan dengan konteks process pemanggil tanpa perlu menyisipkannya secara manual ke dalam teks pesan. Peristiwa Telemetry dan log yang terstruktur saling melengkapi, yaitu yang pertama untuk pengukuran yang diagregasi dan yang kedua untuk jejak peristiwa yang dibaca oleh manusia.

Ringkasan#

• Event Telemetry dinamai dengan daftar atom, dibawa :telemetry.execute/3 beserta pengukuran berupa angka dan metadata konteks, lalu diterima handler yang dipasang melalui :telemetry.attach/4.
• Handler dijalankan secara sinkron di process pemancar, sehingga handler yang lambat menunda pemancarnya.
• Logger.configure(level: :warning) membuang pesan di bawah ambang tersebut, dan perilakunya dapat dibuktikan dengan ExUnit.CaptureLog.capture_log/2 yang tidak mengubah level yang berlaku.
• Metadata Logger tersimpan per process dan melengkapi setiap pesan dengan konteks yang dapat diformat serta diolah sebagai data.

Referensi#

• Telemetry — Hexdocs — dokumentasi attach, execute, dan kontrak handler.
• Modul Logger — Hexdocs — level, configure, metadata, dan formatter.
• Modul ExUnit.CaptureLog — Hexdocs — perekam log sementara untuk pengujian.