Customizing phoenix request log output

Start off by two apologies. First I was not able to create post in the pnoenix forum, the “New Topic” button is disabled. So posting in the general forum, hope that is ok. Does tagging do the trick??

Second, I’ve searched the web, the docs, and looked at examples, but this is not in any way obvious to me how to do. So if this has been asked and answered, just point me in the right direction.

Our logs are overwhelmed by phoenix request logging. And after moving to k8s, health checks are taking over. Not a big deal, but we do have to pay more for our logg aggregator. So it would be nice to shorten.

Typical request log result:

Feb 03 09:58:36 PROD Phoenix.Logger [info] [line: 178, function: "phoenix_endpoint_start/4"]   HEAD /api/health 
Feb 03 09:58:36 PROD Phoenix.Logger [info] [line: 191, function: "phoenix_endpoint_stop/4"]   Sent 200 in 2ms 

Is there any way to shorten this to one line. E.g.:

Feb 03 09:58:36 PROD Phoenix.Logger [info] [line: 191, function: "phoenix_endpoint_stop/4"] Sent 200 in 2ms HEAD /api/health    

Not important that it has this exact format, but it is nice to have all the information on one line.

And a bonus follow up. Is it possible to filter out specific routes, e.g. we are not really interested in request logging of the /api/health path.

Best regards,
Alf Kristian

Hey! Amusingly we were just musing about the health check issue today, which prompted Dynamic Phoenix.Logger level by mcrumm · Pull Request #4196 · phoenixframework/phoenix · GitHub

What we’ve done in the meantime is that we created a plug to wrap Plug.Telemetry that let us filter out our health / readiness / liveliness checks eg:

  plug MyAppWeb.EndpointTelemetry,
    except: ["alive", "health", "ready"]

where that module is:

defmodule MyAppWeb.EndpointTelemetry do
  @moduledoc """
  A plug to conditionally instrument a `Phoenix.Endpoint` with :telemetry events.

  To disable telemetry for a **path prefix**, add the except option:

      plug MyAPpWeb.EndpointTelemetry, except: ["status"]

  This will disable telemetry for all requests to paths
  starting with "/status", for instance:

  - `/status/alive`
  - `/status/health`
  - `/status/ready`

  To disable logging for the root path, add the empty string:

      plug MyAppWeb.EndpointTelemetry, except: [""]
  """
  @behaviour Plug
  alias Plug.Telemetry, as: PlugTelemetry

  @event_prefix [:phoenix, :endpoint]

  @impl true
  def init(opts) do
    {except, _opts} = Keyword.pop(opts, :except, [])
    telemetry_opts = PlugTelemetry.init(event_prefix: @event_prefix)
    validate_telemetry_init_has_not_changed!(telemetry_opts)

    {except, telemetry_opts}
  end

  @impl true
  def call(conn, {except, opts}) do
    prefix = path_for_prefix(conn.path_info)
    opts = if prefix in except, do: disable_logging(opts), else: opts

    PlugTelemetry.call(conn, opts)
  end

  defp path_for_prefix([]), do: ""
  defp path_for_prefix([prefix | _]), do: prefix

  defp disable_logging({start_event, end_event, opts}) do
    {start_event, end_event, Keyword.put(opts, :log, false)}
  end

  defp validate_telemetry_init_has_not_changed!(
         {[:phoenix, :endpoint, _], [:phoenix, :endpoint, _], opts}
       )
       when is_list(opts),
       do: :ok

  defp validate_telemetry_init_has_not_changed!(other) do
    raise ArgumentError, """
    Plug.Telemetry options have changed, expected a tuple {start_event, end_event, opts}, got:

    #{inspect(other)}
    """
  end
end

And then of course make sure to add log: false to the actual route in your router.

EDIT: The second thing I should add is that I want to recommend the logger_json package to produce structured logs, this has been extremely helpful for us to make it easier to manage / organize our logs once they have been ingested into a centralized log manager.

3 Likes

Re-reading your specific use case, the plug we wrote won’t make it super easy to ignore "/api/health" specifically and not other "/api/*" paths so there may be a bit of exercise for the reader to make your situation work.

If you get stuck let me know and I’ll take a crack at it.

1 Like

Great thanks for your help for now. Will try to implement this as soon as possible. Definitely get back to you with follow ups, or even solutions to my specific problem.

So did a small tweak to your code to make it work for our use case. Guess this is not a general solution though. but for inspiration to others.

  @impl true
  def call(conn, {except, opts}) do
    opts =
      if Enum.find(except, &String.starts_with?(conn.request_path, &1)),
        do: disable_logging(opts),
        else: opts

    PlugTelemetry.call(conn, opts)
  end

We have several health checks starting with /api/health, so works for our case. In endpoint we declare:

  plug CoruscantWeb.EndpointTelemetry,
    except: ["/api/health"]

So that reduces our logs quite a bit! Thanks a lot for the help.

Is there a way to join the logging for phoenix_endpoint_start and phoenix_endpoint_stop? I guess instrumenting phoenix_endpoint_stop in some way? The additional log lines gives us really no value.

Like stated above, going from:

Feb 03 09:58:36 PROD Phoenix.Logger [info] [line: 178, function: "phoenix_endpoint_start/4"]   HEAD /api/health 
Feb 03 09:58:36 PROD Phoenix.Logger [info] [line: 191, function: "phoenix_endpoint_stop/4"]   Sent 200 in 2ms 

To, for instance:

Feb 03 09:58:36 PROD Phoenix.Logger [info] [line: 191, function: "phoenix_endpoint_stop/4"] Sent 200 in 2ms HEAD /api/health    
2 Likes