arcana

defmodule Arcana.Telemetry do
  @moduledoc """
  Telemetry events emitted by Arcana.

  Arcana uses the standard `:telemetry` library to emit events for observability.
  You can attach handlers to these events for logging, metrics, or tracing.

  ## Events

  All events are emitted using `:telemetry.span/3`, which automatically generates
  `:start`, `:stop`, and `:exception` events.

  ### Ingest Events

  * `[:arcana, :ingest, :start]` - Emitted when document ingestion begins.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{text: String.t(), repo: module(), collection: String.t()}`

  * `[:arcana, :ingest, :stop]` - Emitted when document ingestion completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{document: Document.t(), chunk_count: integer}`

  * `[:arcana, :ingest, :exception]` - Emitted when document ingestion fails.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{kind: atom(), reason: term(), stacktrace: list()}`

  ### Search Events

  * `[:arcana, :search, :start]` - Emitted when a search query begins.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{query: String.t(), repo: module(), mode: atom(), limit: integer}`

  * `[:arcana, :search, :stop]` - Emitted when a search query completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{results: list(), result_count: integer}`

  * `[:arcana, :search, :exception]` - Emitted when a search query fails.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{kind: atom(), reason: term(), stacktrace: list()}`

  ### Ask Events (RAG)

  * `[:arcana, :ask, :start]` - Emitted when a RAG question begins.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{question: String.t(), repo: module()}`

  * `[:arcana, :ask, :stop]` - Emitted when a RAG question completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{answer: String.t(), context_count: integer}`

  * `[:arcana, :ask, :exception]` - Emitted when a RAG question fails.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{kind: atom(), reason: term(), stacktrace: list()}`

  ### Embed Events

  * `[:arcana, :embed, :start]` - Emitted when embedding generation begins.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{text: String.t()}`

  * `[:arcana, :embed, :stop]` - Emitted when embedding generation completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{dimensions: integer}`

  * `[:arcana, :embed, :exception]` - Emitted when embedding generation fails.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{kind: atom(), reason: term(), stacktrace: list()}`

  ### LLM Events

  * `[:arcana, :llm, :complete, :start]` - Emitted when an LLM call begins.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{model: String.t(), prompt_length: integer, context_count: integer}`

  * `[:arcana, :llm, :complete, :stop]` - Emitted when an LLM call completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{success: boolean, response_length: integer}` or `%{success: false, error: String.t()}`

  * `[:arcana, :llm, :complete, :exception]` - Emitted when an LLM call fails.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{kind: atom(), reason: term(), stacktrace: list()}`

  ### Agent Pipeline Events

  Each step in the Agent pipeline emits `:start`, `:stop`, and `:exception` events:

  * `[:arcana, :agent, :rewrite, :*]` - Query rewriting step.
    * Stop metadata: `%{query: String.t()}`

  * `[:arcana, :agent, :select, :*]` - Collection selection step.
    * Stop metadata: `%{selected: [String.t()]}`

  * `[:arcana, :agent, :expand, :*]` - Query expansion step.
    * Stop metadata: `%{expanded_query: String.t()}`

  * `[:arcana, :agent, :decompose, :*]` - Question decomposition step.
    * Stop metadata: `%{sub_question_count: integer}`

  * `[:arcana, :agent, :search, :*]` - Vector search step.
    * Stop metadata: `%{total_chunks: integer}`

  * `[:arcana, :agent, :rerank, :*]` - Chunk reranking step.
    * Stop metadata: `%{kept: integer, original: integer}`

  * `[:arcana, :agent, :answer, :*]` - Answer generation step.
    * Stop metadata: `%{}`

  * `[:arcana, :agent, :self_correct, :*]` - Self-correction iteration.
    * Stop metadata: `%{attempt: integer}`

  ### GraphRAG Events

  When using GraphRAG features (`graph: true`), these events are emitted:

  * `[:arcana, :graph, :build, :start]` - Emitted when graph building begins during ingest.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{chunk_count: integer, collection: String.t()}`

  * `[:arcana, :graph, :build, :stop]` - Emitted when graph building completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{entity_count: integer, relationship_count: integer}`

  * `[:arcana, :graph, :build, :exception]` - Emitted when graph building fails.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{kind: atom(), reason: term(), stacktrace: list()}`

  * `[:arcana, :graph, :search, :start]` - Emitted when graph-enhanced search begins.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{query: String.t(), entity_count: integer}`

  * `[:arcana, :graph, :search, :stop]` - Emitted when graph-enhanced search completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{graph_result_count: integer, combined_count: integer}`

  * `[:arcana, :graph, :search, :exception]` - Emitted when graph-enhanced search fails.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{kind: atom(), reason: term(), stacktrace: list()}`

  * `[:arcana, :graph, :ner, :start]` - Emitted when NER entity extraction begins.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{text: String.t()}`

  * `[:arcana, :graph, :ner, :stop]` - Emitted when NER entity extraction completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{entity_count: integer}`

  * `[:arcana, :graph, :relationship_extraction, :start]` - Emitted when relationship extraction begins.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{text: String.t()}`

  * `[:arcana, :graph, :relationship_extraction, :stop]` - Emitted when relationship extraction completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{relationship_count: integer}`

  * `[:arcana, :graph, :community_detection, :start]` - Emitted when community detection begins.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{entity_count: integer}`

  * `[:arcana, :graph, :community_detection, :stop]` - Emitted when community detection completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{community_count: integer}`

  * `[:arcana, :graph, :community_summary, :start]` - Emitted when community summarization begins.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{entity_count: integer}`

  * `[:arcana, :graph, :community_summary, :stop]` - Emitted when community summarization completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{summary_length: integer}`

  ### VectorStore Events

  * `[:arcana, :vector_store, :store, :start]` - Emitted when storing a vector.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{collection: String.t(), id: String.t()}`

  * `[:arcana, :vector_store, :store, :stop]` - Emitted when vector storage completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{backend: atom()}`

  * `[:arcana, :vector_store, :search, :start]` - Emitted when vector search begins.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{collection: String.t(), limit: integer}`

  * `[:arcana, :vector_store, :search, :stop]` - Emitted when vector search completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{backend: atom(), result_count: integer}`

  * `[:arcana, :vector_store, :search_text, :start]` - Emitted when fulltext search begins.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{collection: String.t(), query: String.t(), limit: integer}`

  * `[:arcana, :vector_store, :search_text, :stop]` - Emitted when fulltext search completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{backend: atom(), result_count: integer}`

  * `[:arcana, :vector_store, :delete, :start]` - Emitted when deleting a vector.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{collection: String.t(), id: String.t()}`

  * `[:arcana, :vector_store, :delete, :stop]` - Emitted when vector deletion completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{backend: atom()}`

  * `[:arcana, :vector_store, :clear, :start]` - Emitted when clearing a collection.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{collection: String.t()}`

  * `[:arcana, :vector_store, :clear, :stop]` - Emitted when collection clearing completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{backend: atom()}`

  ### GraphStore Events

  * `[:arcana, :graph_store, :persist_entities, :start]` - Emitted when persisting entities.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{collection_id: String.t(), entity_count: integer}`

  * `[:arcana, :graph_store, :persist_entities, :stop]` - Emitted when entity persistence completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{backend: atom()}`

  * `[:arcana, :graph_store, :persist_relationships, :start]` - Emitted when persisting relationships.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{relationship_count: integer}`

  * `[:arcana, :graph_store, :persist_relationships, :stop]` - Emitted when relationship persistence completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{backend: atom()}`

  * `[:arcana, :graph_store, :persist_mentions, :start]` - Emitted when persisting mentions.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{mention_count: integer}`

  * `[:arcana, :graph_store, :persist_mentions, :stop]` - Emitted when mention persistence completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{backend: atom()}`

  * `[:arcana, :graph_store, :search, :start]` - Emitted when searching graph store.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{entity_count: integer}`

  * `[:arcana, :graph_store, :search, :stop]` - Emitted when graph search completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{backend: atom(), result_count: integer}`

  * `[:arcana, :graph_store, :delete_by_chunks, :start]` - Emitted when deleting by chunks.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{chunk_count: integer}`

  * `[:arcana, :graph_store, :delete_by_chunks, :stop]` - Emitted when chunk deletion completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{backend: atom()}`

  * `[:arcana, :graph_store, :delete_by_collection, :start]` - Emitted when deleting by collection.
    * Measurement: `%{system_time: integer}`
    * Metadata: `%{collection_id: String.t()}`

  * `[:arcana, :graph_store, :delete_by_collection, :stop]` - Emitted when collection deletion completes.
    * Measurement: `%{duration: integer}`
    * Metadata: `%{backend: atom()}`

  ## Quick Start with Built-in Logger

  For quick setup, use the built-in logger:

      # In your application's start/2
      Arcana.Telemetry.Logger.attach()

  This logs all events with timing info. See `Arcana.Telemetry.Logger` for options.

  ## Custom Handler

  For custom handling, attach your own handler:

      defmodule MyApp.ArcanaLogger do
        require Logger

        def setup do
          events = [
            [:arcana, :ingest, :stop],
            [:arcana, :search, :stop],
            [:arcana, :ask, :stop],
            [:arcana, :embed, :stop]
          ]

          :telemetry.attach_many("arcana-logger", events, &handle_event/4, nil)
        end

        def handle_event([:arcana, :ingest, :stop], measurements, metadata, _config) do
          Logger.info("Ingested document \#{metadata.document.id} with \#{metadata.chunk_count} chunks in \#{format_duration(measurements.duration)}")
        end

        def handle_event([:arcana, :search, :stop], measurements, metadata, _config) do
          Logger.info("Search returned \#{metadata.result_count} results in \#{format_duration(measurements.duration)}")
        end

        def handle_event([:arcana, :ask, :stop], measurements, metadata, _config) do
          Logger.info("RAG answered with \#{metadata.context_count} context chunks in \#{format_duration(measurements.duration)}")
        end

        def handle_event([:arcana, :embed, :stop], measurements, _metadata, _config) do
          Logger.debug("Generated embedding in \#{format_duration(measurements.duration)}")
        end

        defp format_duration(duration) do
          duration
          |> System.convert_time_unit(:native, :millisecond)
          |> then(&"\#{&1}ms")
        end
      end

  Then call `MyApp.ArcanaLogger.setup()` in your application startup.

  ## Integration with Metrics Libraries

  These telemetry events work with metrics libraries like:

  * `telemetry_metrics` - Define metrics based on these events
  * `telemetry_poller` - Periodically report metrics
  * `prom_ex` - Export to Prometheus

  Example with `telemetry_metrics`:

      defmodule MyApp.Metrics do
        import Telemetry.Metrics

        def metrics do
          [
            counter("arcana.ingest.stop.duration", unit: {:native, :millisecond}),
            counter("arcana.search.stop.duration", unit: {:native, :millisecond}),
            summary("arcana.search.stop.result_count"),
            distribution("arcana.embed.stop.duration", unit: {:native, :millisecond})
          ]
        end
      end
  """

  @doc """
  Wraps a function call with telemetry span events.

  This is a convenience function used internally by Arcana to emit
  consistent telemetry events.
  """
  def span(event_prefix, start_metadata, fun)
      when is_list(event_prefix) and is_function(fun, 0) do
    :telemetry.span(event_prefix, start_metadata, fn ->
      result = fun.()
      {result, %{}}
    end)
  end

  @doc """
  Wraps a function call with telemetry span events, allowing custom stop metadata.

  The function should return `{result, stop_metadata}` where `stop_metadata`
  is a map of additional metadata to include in the stop event.
  """
  def span_with_metadata(event_prefix, start_metadata, fun)
      when is_list(event_prefix) and is_function(fun, 0) do
    :telemetry.span(event_prefix, start_metadata, fun)
  end
end