Expose GraphQL operation in logs with Absinthe

@remiOctober 6th, 2022

A few months ago, we started using this pattern (originally written by our own @EtienneStPierre) in our GraphQL APIs (using Absinthe) and we just brought it back to our Elixir boilerplate.

GraphQL HTTP requests look pretty bland in logs. Given this simple query:

query CurrentUserEmail {
  viewer {
    email
  }
}

It will always show up in logs as:

20:33:56.107 request_id=FxtToINh7z7RLpsAAAKB [info] POST /graphql
20:33:56.239 request_id=FxtToINh7z7RLpsAAAKB [info] Sent 200 in 84ms

We use named operations in all of our client requests so we thought it would be a good idea to include operation names in logs.

So we created this pretty simple Absinthe middleware:

defmodule ElixirBoilerplateGraphQL.OperationNameLogger do
  @behaviour Absinthe.Middleware

  alias Absinthe.Blueprint.Document.Operation

  def call(resolution, _opts) do
    case Enum.find(resolution.path, &current_operation?/1) do
      %Operation{name: name} when not is_nil(name) ->
        Logger.metadata(graphql_operation_name: name)

      _ ->
        Logger.metadata(graphql_operation_name: "#NULL")
    end

    resolution
  end

  defp current_operation?(%Operation{current: true}), do: true
  defp current_operation?(_), do: false
end

It extracts the name of the current (because you can declare multiple operations but only one can be executed) operation and adds it the logger’s metadata.

Now we just have to allow the graphql_operation_name metadata in the logger’s configuration:

config :logger, :console,
  format: "$time $metadata[$level] $message\n",
  level: :info,
- metadata: ~w(request_id)a
+ metadata: ~w(request_id graphql_operation_name)a

And now GraphQL requests sent via HTTP are now a little bit more useful in logs!

20:33:56.107 request_id=FxtToINh7z7RLpsAAAKB [info] POST /graphql
20:33:56.239 request_id=FxtToINh7z7RLpsAAAKB graphql_operation_name=CurrentUserEmail [info] Sent 200 in 84ms

Cool cool cool! 😎