diff --git a/config/config.exs b/config/config.exs index d2d855e..fd3adb7 100644 --- a/config/config.exs +++ b/config/config.exs @@ -1 +1,11 @@ use Mix.Config + +if Mix.env() == :test do + config :opencensus, + send_interval_ms: 1, + reporters: [{Opencensus.Absinthe.TestSupport.SpanCaptureReporter, []}] +end + +config :logger, + backends: [:console], + level: :warn diff --git a/lib/opencensus/absinthe/middleware.ex b/lib/opencensus/absinthe/middleware.ex index 496e833..2cafc8c 100644 --- a/lib/opencensus/absinthe/middleware.ex +++ b/lib/opencensus/absinthe/middleware.ex @@ -24,7 +24,20 @@ defmodule Opencensus.Absinthe.Middleware do end @doc false + @spec on_complete(Resolution.t(), span_ctx: :opencensus.span_ctx()) :: Resolution.t() def on_complete(%{state: :resolved} = resolution, span_ctx: span_ctx) do + # credo:disable-for-next-line + error_count = length(resolution.errors) + status = if error_count == 0, do: "ok", else: "error" + + :oc_trace.put_attributes( + %{ + "absinthe.field.resolution_error_count" => error_count, + "absinthe.field.resolution_status" => status + }, + span_ctx + ) + :oc_trace.finish_span(span_ctx) resolution end diff --git a/lib/opencensus/absinthe/phase/pop.ex b/lib/opencensus/absinthe/phase/pop.ex index ba70269..bc26422 100644 --- a/lib/opencensus/absinthe/phase/pop.ex +++ b/lib/opencensus/absinthe/phase/pop.ex @@ -5,11 +5,32 @@ defmodule Opencensus.Absinthe.Phase.Pop do alias Absinthe.Blueprint alias Absinthe.Phase + alias Opencensus.Absinthe.Acc @impl true @spec run(Blueprint.t(), keyword()) :: Phase.result_t() def run(blueprint, _opts \\ []) do - :ocp.finish_span() + acc = Acc.get(blueprint) + + {status, error_count} = + case blueprint do + %{result: %{errors: errors}} -> {:error, length(errors)} + _ -> {:ok, 0} + end + + :oc_trace.put_attributes( + %{ + "absinthe.blueprint.error_count" => error_count, + "absinthe.blueprint.status" => Atom.to_string(status) + }, + acc.span_ctx + ) + + # Finish our span, even if it isn't current: + :oc_trace.finish_span(acc.span_ctx) + # Restore our parent span: + :ocp.with_span_ctx(acc.parent_span_ctx) + {:ok, blueprint} end end diff --git a/mix.exs b/mix.exs index cf4cdb4..dfc8fb8 100644 --- a/mix.exs +++ b/mix.exs @@ -11,6 +11,7 @@ defmodule Opencensus.Absinthe.MixProject do dialyzer: dialyzer(), docs: docs(), elixir: "~> 1.5", + elixirc_paths: elixirc_paths(Mix.env()), package: package(), preferred_cli_env: [ coveralls: :test, @@ -36,6 +37,9 @@ defmodule Opencensus.Absinthe.MixProject do ] end + defp elixirc_paths(:test), do: ["lib", "test/support"] + defp elixirc_paths(_), do: ["lib"] + defp package() do [ licenses: ["Apache 2.0"], @@ -54,13 +58,15 @@ defmodule Opencensus.Absinthe.MixProject do {:absinthe_plug, "~> 1.4.0", optional: true}, {:credo, "~> 1.1.0", only: :test}, {:dialyxir, "~> 1.0.0-rc.6", only: :dev, runtime: false}, - {:ex_doc, ">= 0.0.0", only: :docs}, + {:ex_doc, ">= 0.0.0", only: [:docs, :test]}, {:excoveralls, "~> 0.11.1", only: :test}, {:inch_ex, "~> 2.0.0", only: :docs}, + {:jason, "~> 1.0", only: [:docs, :test]}, {:licensir, "~> 0.4.0", only: :test}, {:mix_test_watch, "~> 0.8", only: :test}, {:opencensus, "~> 0.9.2"}, - {:opencensus_elixir, "~> 0.4.0"} + {:opencensus_plug, "~> 0.3", only: :test}, + {:telemetry, "~> 0.4", only: :test} ] end diff --git a/mix.lock b/mix.lock index 3bc392a..f5d3a21 100644 --- a/mix.lock +++ b/mix.lock @@ -25,7 +25,7 @@ "mix_test_watch": {:hex, :mix_test_watch, "0.9.0", "c72132a6071261893518fa08e121e911c9358713f62794a90c95db59042af375", [:mix], [{:file_system, "~> 0.2.1 or ~> 0.3", [hex: :file_system, repo: "hexpm", optional: false]}], "hexpm"}, "nimble_parsec": {:hex, :nimble_parsec, "0.5.0", "90e2eca3d0266e5c53f8fbe0079694740b9c91b6747f2b7e3c5d21966bba8300", [:mix], [], "hexpm"}, "opencensus": {:hex, :opencensus, "0.9.2", "ab36b0c4e4500b976180bd088cea7520d345711a72df2d7188e2d7b9573a8728", [:rebar3], [{:counters, "~> 0.2.1", [hex: :counters, repo: "hexpm", optional: false]}, {:ctx, "~> 0.5", [hex: :ctx, repo: "hexpm", optional: false]}, {:wts, "~> 0.3", [hex: :wts, repo: "hexpm", optional: false]}], "hexpm"}, - "opencensus_elixir": {:hex, :opencensus_elixir, "0.4.0", "ac00f3b027841ba47ad8a9205c442c2e5473c1ffeb45e9c2569cccd5d35fa814", [:mix], [{:opencensus, "~> 0.9", [hex: :opencensus, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm"}, + "opencensus_plug": {:hex, :opencensus_plug, "0.3.0", "ff04bdd59c39dee66fc56086e9300818325afe184a2e8919a8bb47912ad5164c", [:mix], [{:opencensus, "~> 0.9", [hex: :opencensus, repo: "hexpm", optional: false]}, {:plug, "~> 1.6", [hex: :plug, repo: "hexpm", optional: false]}], "hexpm"}, "parse_trans": {:hex, :parse_trans, "3.3.0", "09765507a3c7590a784615cfd421d101aec25098d50b89d7aa1d66646bc571c1", [:rebar3], [], "hexpm"}, "plug": {:hex, :plug, "1.8.2", "0bcce1daa420f189a6491f3940cc77ea7fb1919761175c9c3b59800d897440fc", [:mix], [{:mime, "~> 1.0", [hex: :mime, repo: "hexpm", optional: false]}, {:plug_crypto, "~> 1.0", [hex: :plug_crypto, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4", [hex: :telemetry, repo: "hexpm", optional: true]}], "hexpm"}, "plug_crypto": {:hex, :plug_crypto, "1.0.0", "18e49317d3fa343f24620ed22795ec29d4a5e602d52d1513ccea0b07d8ea7d4d", [:mix], [], "hexpm"}, diff --git a/test/opencensus_absinthe_test.exs b/test/opencensus_absinthe_test.exs new file mode 100644 index 0000000..ef750cb --- /dev/null +++ b/test/opencensus_absinthe_test.exs @@ -0,0 +1,400 @@ +defmodule Opencensus.AbsintheTest do + use ExUnit.Case, async: false + use Plug.Test + + alias Opencensus.Absinthe.TestSupport.SpanCaptureReporter + alias Opencensus.Absinthe.TestSupport.SpanContext + + defmodule MyApp.Schema do + use Absinthe.Schema + + @impl Absinthe.Schema + def middleware(middleware, field, object) do + Opencensus.Absinthe.middleware(middleware, field, object) + end + + query do + field :item, :item, meta: [trace: true] do + arg(:id, non_null(:integer)) + + resolve(fn %{id: item_id}, _ -> + case item_id do + 0 -> {:ok, %{id: 0, name: "Foo"}} + _ -> {:error, %ArgumentError{message: "404 NOT FOUND"}} + end + end) + end + + field :simulated_error, :item, meta: [trace: true] do + arg(:id, non_null(:integer)) + + resolve(fn %{id: _}, _ -> + {:error, "Something went horribly wrong."} + end) + end + + field :simulated_crash, :item, meta: [trace: true] do + arg(:id, non_null(:integer)) + + resolve(fn %{id: _}, _ -> + IO.inspect(:ocp.current_span_ctx(), label: "naughty resolver current_span_ctx") + raise ArgumentError, message: "NAUGHTY RESOLVER" + end) + end + end + + @desc "An item" + object :item do + field(:id, :integer) + field(:name, :string) + end + end + + defmodule SpanPopper do + @spec unwind_span_failures(:opencensus.span_ctx() | %SpanContext{}) :: nil + def unwind_span_failures(target_span_ctx) when is_tuple(target_span_ctx) do + target_span_ctx + |> SpanContext.from() + |> dead_child_spans(:ocp.current_span_ctx(), []) + |> IO.inspect(label: "dead spans") + |> Enum.each(&:oc_trace.finish_span(&1)) + + :ocp.with_span_ctx(target_span_ctx |> IO.inspect(label: "restoring")) + end + + @spec dead_child_spans(%SpanContext{}, :opencensus.span_ctx(), [:opencensus.span_ctx()]) :: [ + :opencensus.span_ctx() + ] + defp dead_child_spans(%SpanContext{} = target, span_ctx, spans) do + %{span_id: span_id, trace_id: trace_id} = target + + case SpanContext.from(span_ctx) do + %{span_id: ^span_id} -> + spans |> Enum.reverse() + + %{trace_id: ^trace_id} -> + dead_child_spans(target, :oc_trace.parent_span_ctx(span_ctx), [span_ctx | spans]) + + _ -> + [] + end + end + end + + defmodule MyApp.TracePlug do + use Opencensus.Plug.Trace + end + + defmodule MyApp.Plug do + use Plug.Builder + + plug(MyApp.TracePlug) + + plug(Absinthe.Plug, + json_codec: Jason, + schema: MyApp.Schema, + pipeline: {__MODULE__, :traced_pipeline} + ) + + def call(conn, opts) do + span_ctx = :ocp.current_span_ctx() + + try do + super(conn, opts) + after + SpanPopper.unwind_span_failures(span_ctx) + end + end + + def traced_pipeline(config, pipeline_opts \\ []) do + config + |> Absinthe.Plug.default_pipeline(pipeline_opts) + |> Opencensus.Absinthe.add_phases() + end + end + + setup_all do + :ok = Application.ensure_started(:mime) + :ok = Application.ensure_started(:plug_crypto) + :ok = Application.ensure_started(:plug) + :ok = Application.ensure_started(:telemetry) + :ok + end + + setup do + old_ctx = :ocp.current_span_ctx() + on_exit(make_ref(), fn -> :ocp.with_span_ctx(old_ctx) end) + :ocp.with_span_ctx(:undefined) + + SpanCaptureReporter.attach() + on_exit(make_ref(), &SpanCaptureReporter.detach/0) + + :ocp.with_child_span("test span") + span_ctx = :ocp.current_span_ctx() + assert span_ctx != :undefined + + %{span_ctx: span_ctx} + end + + describe "integration tests:" do + test "happy path", %{span_ctx: span_ctx} do + result = + conn(:post, "/", ~S'{ item(id: 0) { name } }') + |> put_req_header("content-type", "application/graphql") + |> put_req_header("traceparent", traceparent(span_ctx)) + |> Plug.Parsers.call(plug_parser_opts()) + |> MyApp.Plug.call(MyApp.Plug.init([])) + + assert result.status == 200 + assert result.resp_body == ~S'{"data":{"item":{"name":"Foo"}}}' + + assert :ocp.current_span_ctx() == span_ctx + :ocp.finish_span() + + spans = SpanCaptureReporter.collect() |> Enum.sort_by(& &1.start_time) + [_, request_span, blueprint_span, field_span] = spans + + assert request_span.name == "/" + + assert_contains!(blueprint_span, %{ + name: "Blueprint", + trace_id: request_span.trace_id, + parent_span_id: request_span.span_id + }) + + assert blueprint_span.attributes == %{ + "absinthe.blueprint.error_count" => 0, + "absinthe.blueprint.status" => "ok" + } + + assert_contains!(field_span, %{ + name: "Opencensus.AbsintheTest.MyApp.Schema:item", + trace_id: blueprint_span.trace_id, + parent_span_id: blueprint_span.span_id + }) + + assert Map.keys(field_span.attributes) == [ + "absinthe.field.file", + "absinthe.field.line", + "absinthe.field.module", + "absinthe.field.name", + "absinthe.field.resolution_error_count", + "absinthe.field.resolution_status", + "absinthe.field.type" + ] + + assert_contains!(field_span.attributes, %{ + "absinthe.field.module" => "Opencensus.AbsintheTest.MyApp.Schema", + "absinthe.field.name" => "item", + "absinthe.field.resolution_error_count" => 0, + "absinthe.field.resolution_status" => "ok" + }) + end + + test "field resolver error", %{span_ctx: span_ctx} do + result = + conn(:post, "/", ~S'{ simulated_error(id: 0) { name } }') + |> put_req_header("content-type", "application/graphql") + |> put_req_header("traceparent", traceparent(span_ctx)) + |> Plug.Parsers.call(plug_parser_opts()) + |> MyApp.Plug.call(MyApp.Plug.init([])) + + assert result.status == 200 + + assert result.resp_body |> Jason.decode!() == %{ + "data" => %{"simulated_error" => nil}, + "errors" => [ + %{ + "locations" => [%{"column" => 0, "line" => 1}], + "message" => "Something went horribly wrong.", + "path" => ["simulated_error"] + } + ] + } + + assert :ocp.current_span_ctx() == span_ctx + :ocp.finish_span() + + spans = SpanCaptureReporter.collect() |> Enum.sort_by(& &1.start_time) + [_, request_span, blueprint_span, field_span] = spans + + assert request_span.name == "/" + + assert_contains!(blueprint_span, %{ + name: "Blueprint", + trace_id: request_span.trace_id, + parent_span_id: request_span.span_id + }) + + assert blueprint_span.attributes == %{ + "absinthe.blueprint.error_count" => 1, + "absinthe.blueprint.status" => "error" + } + + assert_contains!(field_span, %{ + name: "Opencensus.AbsintheTest.MyApp.Schema:simulated_error", + trace_id: blueprint_span.trace_id, + parent_span_id: blueprint_span.span_id + }) + + assert Map.keys(field_span.attributes) == [ + "absinthe.field.file", + "absinthe.field.line", + "absinthe.field.module", + "absinthe.field.name", + "absinthe.field.resolution_error_count", + "absinthe.field.resolution_status", + "absinthe.field.type" + ] + + assert_contains!(field_span.attributes, %{ + "absinthe.field.module" => "Opencensus.AbsintheTest.MyApp.Schema", + "absinthe.field.name" => "simulated_error", + "absinthe.field.resolution_error_count" => 1, + "absinthe.field.resolution_status" => "error" + }) + end + + defp traceparent(span_ctx) do + [{"traceparent", iolist}] = :oc_propagation_http_tracecontext.to_headers(span_ctx) + iolist |> to_string + end + + test "field resolver crash", %{span_ctx: span_ctx} do + result = + try do + conn(:post, "/", ~S'{ simulated_crash(id: 0) { name } }') + |> put_req_header("content-type", "application/graphql") + |> put_req_header("traceparent", traceparent(span_ctx)) + |> Plug.Parsers.call(plug_parser_opts()) + |> MyApp.Plug.call(MyApp.Plug.init([])) + rescue + err -> err + end + + # We got the error, all the way to the top: + assert result == %ArgumentError{message: "NAUGHTY RESOLVER"} + + # Our traces got unwound: + assert :ocp.current_span_ctx() == span_ctx + :ocp.finish_span() + + # TODO the reason this isn't working the way we want is because we are NOT tracking the + # resolver's trace using OCP. We need to find another way: + [_, request_span, blueprint_span, field_span] = + SpanCaptureReporter.collect() + |> Enum.sort_by(& &1.start_time) + |> IO.inspect(label: "all spans") + + assert request_span.name == "/" + + assert_contains!(blueprint_span, %{ + name: "Blueprint", + trace_id: request_span.trace_id, + parent_span_id: request_span.span_id + }) + + assert blueprint_span.attributes == %{ + "absinthe.blueprint.error_count" => 1, + "absinthe.blueprint.status" => "error" + } + + assert_contains!(field_span, %{ + name: "Opencensus.AbsintheTest.MyApp.Schema:simulated_error", + trace_id: blueprint_span.trace_id, + parent_span_id: blueprint_span.span_id + }) + + assert Map.keys(field_span.attributes) == [ + "absinthe.field.file", + "absinthe.field.line", + "absinthe.field.module", + "absinthe.field.name", + "absinthe.field.resolution_error_count", + "absinthe.field.resolution_status", + "absinthe.field.type" + ] + + assert_contains!(field_span.attributes, %{ + "absinthe.field.module" => "Opencensus.AbsintheTest.MyApp.Schema", + "absinthe.field.name" => "simulated_error", + "absinthe.field.resolution_error_count" => 1, + "absinthe.field.resolution_status" => "error" + }) + end + + test "bad query", %{span_ctx: span_ctx} do + result = + conn(:post, "/", ~S'{ error(id: "foo") { name } }') + |> put_req_header("content-type", "application/graphql") + |> put_req_header("traceparent", traceparent(span_ctx)) + |> Plug.Parsers.call(plug_parser_opts()) + |> MyApp.Plug.call(MyApp.Plug.init([])) + + assert result.status == 200 + + assert result.resp_body |> Jason.decode!() == %{ + "errors" => [ + %{ + "locations" => [%{"column" => 0, "line" => 1}], + "message" => "Cannot query field \"error\" on type \"RootQueryType\"." + }, + %{ + "locations" => [%{"column" => 0, "line" => 1}], + "message" => + "Unknown argument \"id\" on field \"error\" of type \"RootQueryType\"." + } + ] + } + + assert :ocp.current_span_ctx() == span_ctx + :ocp.finish_span() + + [_, request_span, blueprint_span] = + SpanCaptureReporter.collect() |> Enum.sort_by(& &1.start_time) + + assert request_span.name == "/" + + assert Map.take(blueprint_span, [:name, :trace_id, :parent_span_id]) == %{ + name: "Blueprint", + trace_id: request_span.trace_id, + parent_span_id: request_span.span_id + } + + assert blueprint_span.attributes == %{ + "absinthe.blueprint.error_count" => 2, + "absinthe.blueprint.status" => "error" + } + end + end + + def assert_contains!(%_{} = bigger, smaller) when is_map(smaller), + do: assert_contains!(Map.from_struct(bigger), smaller) + + def assert_contains!(bigger, smaller) when is_map(bigger) and is_map(smaller) do + problems = + smaller + |> Map.to_list() + |> Enum.map(&check_against(&1, bigger)) + |> Enum.filter(&(&1 != nil)) + + assert problems == [] + end + + defp check_against({key, wanted}, map) when is_map(map) do + got = Map.get(map, key) + + cond do + not Map.has_key?(map, key) -> {:missing, key: key} + got != wanted -> {:mismatch, key: key, got: got, wanted: wanted} + true -> nil + end + end + + def plug_parser_opts, + do: + Plug.Parsers.init( + parsers: [:urlencoded, :multipart, :json, Absinthe.Plug.Parser], + json_decoder: Jason + ) +end diff --git a/test/support/span.ex b/test/support/span.ex new file mode 100644 index 0000000..0d332c7 --- /dev/null +++ b/test/support/span.ex @@ -0,0 +1,13 @@ +defmodule Opencensus.Absinthe.TestSupport.Span do + @moduledoc "Converts `:opencensus.span` records to structs." + + require Record + @fields Record.extract(:span, from_lib: "opencensus/include/opencensus.hrl") + Record.defrecordp(:span, @fields) + + defstruct Keyword.keys(@fields) + + @doc "Convert a span." + @spec from(:opencensus.span()) :: %__MODULE__{} + def from(record) when Record.is_record(record, :span), do: struct!(__MODULE__, span(record)) +end diff --git a/test/support/span_capture_reporter.ex b/test/support/span_capture_reporter.ex new file mode 100644 index 0000000..93544f7 --- /dev/null +++ b/test/support/span_capture_reporter.ex @@ -0,0 +1,72 @@ +defmodule Opencensus.Absinthe.TestSupport.SpanCaptureReporter do + @moduledoc """ + An `:opencensus.reporter` to capture spans for tests. + + `:oc_reporter` can't unregister reporters, but `:telemetry` can detach handlers, so we configure + `:opencensus` to send spans to use our reporter, in `mix.exs`: + + ```elixir + if Mix.env() == :test do + config :opencensus, + send_interval_ms: 1, + reporters: [{Opencensus.Absinthe.TestSupport.SpanCaptureReporter, []}] + end + ``` + + It'll call `:telemetry.execute/3` whenever spans are reported. If you've called `attach/0`, + the handler will convert the spans to structs with `Span.from/1` and deliver them to your + process inbox. To collect them, call `collect/0`. When you're finished, call `detach/0`: + + ```elixir + defmodule Opencensus.AbsintheTest do + use ExUnit.Case, async: false + + alias Opencensus.Absinthe.TestSupport.SpanCaptureReporter + + setup do + SpanCaptureReporter.attach() + on_exit(make_ref(), &SpanCaptureReporter.detach/0) + end + + test "can gather spans" do + :ocp.with_child_span("our span name") + :ocp.finish_span() + [span] = SpanCaptureReporter.collect() + assert span.name == "our span name" + end + end + ``` + """ + + alias Opencensus.Absinthe.TestSupport.Span + + @behaviour :oc_reporter + + @impl true + def init([]), do: [] + + @impl true + def report(spans, []) do + :telemetry.execute([__MODULE__], %{}, %{spans: spans}) + :ok + end + + @doc false + def handler([__MODULE__], %{}, %{spans: spans}, pid), do: send(pid, {:spans, spans}) + + @doc "Attach the reporter to deliver spans to your process inbox." + def attach(), do: :telemetry.attach(__MODULE__, [__MODULE__], &handler/4, self()) + + @doc "Detach the reporter to stop delivering spans to your process inbox." + def detach(), do: :telemetry.detach(__MODULE__) + + @doc "Collect spans from your process inbox." + def collect(acc \\ []) do + receive do + {:spans, spans} -> collect(acc ++ spans) + after + 10 -> + acc |> Enum.map(&Span.from/1) + end + end +end diff --git a/test/support/span_context.ex b/test/support/span_context.ex new file mode 100644 index 0000000..21888fb --- /dev/null +++ b/test/support/span_context.ex @@ -0,0 +1,18 @@ +defmodule Opencensus.Absinthe.TestSupport.SpanContext do + @moduledoc "Converts `:opencensus.span_ctx` records to structs." + + require Record + @fields Record.extract(:span_ctx, from_lib: "opencensus/include/opencensus.hrl") + Record.defrecordp(:span_ctx, @fields) + + defstruct Keyword.keys(@fields) + + @doc "Convert a span context." + @spec from(:opencensus.span_ctx() | :undefined) :: %__MODULE__{} + def from(record) + + def from(record) when Record.is_record(record, :span_ctx), + do: struct!(__MODULE__, span_ctx(record)) + + def from(:undefined), do: nil +end