Licet emits :telemetry events for checks, lookups, writes and imports, and the check cache. Attach handlers to them to export metrics or log slow queries.

Span events

Checks, lookups, and writes are wrapped in :telemetry.span/3. Each emits a :start event, then either :stop or :exception:

Event prefixEmitted byMetadata
[:licet, :check]Licet.check/5:resource, :permission, :subject
[:licet, :lookup]Licet.lookup_resources/5:resource_type, :permission, :subject
[:licet, :lookup]Licet.lookup_subjects/5:resource, :permission, :subject_type
[:licet, :write]Licet.write/3, Licet.import/3:count, the number of updates

Measurements follow the :telemetry.span/3 convention:

  • :start has :system_time and :monotonic_time.
  • :stop has :duration and :monotonic_time.
  • :exception has :duration and :monotonic_time, and its metadata adds :kind, :reason, and :stacktrace.

Durations are in native time units. Convert them with System.convert_time_unit/3.

A check that returns {:error, _} still ends with a :stop event. :exception is emitted only when the call raises.

These functions emit no span event: Licet.check_bulk/3, Licet.read/3, Licet.delete/3, Licet.explain/5, and Licet.write_schema/3. check_bulk/3 does emit cache events, below.

Cache events

Each check outside a transaction first looks in the cache. Licet.check_bulk/3 looks up each distinct item, so a bulk call emits one cache event per distinct check:

EventMeasurementsMetadata
[:licet, :cache, :hit]%{count: 1}%{}
[:licet, :cache, :miss]%{count: 1}%{}

Checks inside a transaction and checks with consistency: :full skip the cache and emit neither event.

Metrics

With telemetry_metrics, for example in your application's telemetry supervisor:

import Telemetry.Metrics

[
  summary("licet.check.stop.duration", unit: {:native, :millisecond}),
  summary("licet.lookup.stop.duration", unit: {:native, :millisecond}),
  summary("licet.write.stop.duration", unit: {:native, :millisecond}),
  sum("licet.write.stop.count", measurement: fn _measurements, metadata -> metadata.count end),
  counter("licet.cache.hit.count"),
  counter("licet.cache.miss.count")
]

Logging slow checks

:telemetry.attach(
  "licet-slow-checks",
  [:licet, :check, :stop],
  fn _event, %{duration: duration}, metadata, _config ->
    ms = System.convert_time_unit(duration, :native, :millisecond)

    if ms > 50 do
      Logger.warning("slow Licet check: #{ms}ms #{inspect(metadata)}")
    end
  end,
  nil
)

Use a module function instead of an anonymous function in production, as the :telemetry documentation recommends.