No stack trace in production log

Phoenix Forum Questions / Help
, , ,
1

I’m struggling with the fact that I don’t see stack trace in my production app log.

I’m getting 500 Internal Server Error response.

I try to connect to the running app and enable debug log Logger.configure(level: :debug).
This helps a bit but I still don’t see stack trace.

My current error is Converted error :undef to 500 response.

Without any stack trace I don’t understand where the error is coming from.

Does anybody know how to enable stack trace in production?

UPDATE1: I did more testing on that and discover that I mix release and start app locally I do get stack trace as expected however on my production Ubuntu server I just get

application=phoenix request_id=FwQp3A4z_ymkm3sAAAHh [debug] Converted error ArgumentError to 500 response

I’m using Docker to cross compile the app when I copy it to Ubuntu server where I run it as systemd process.

2

Does this help? Error logging and stack traces in release vs IEx

3

I looked over those replies already. There in no solution offered in any of those.

One person suggest to “add Logger.error(error) to render() in ErrorView” but that seams like a hack and still doesn’t show stack trace.

I’m trying to understand what is the fundamental reason of that happening in production build and why this is default behavior?

4

Phoenix’s default logger is very basic, which is implemented as telemetry event handler at here.

At first, you can disable the default logger by:

config :phoenix, :logger, false

Then, implement you own telemetry event handler for logging.

Recently, I added a JSON logger for my app, so I can give you a basic example:

  1. I implemented a module for handling related telemetry event:
defmodule JSONLog.Logger do
  @moduledoc """
  Instrumenter to handle logging of various Phoenix instrumentation events.
  """

  require Logger

  @doc false
  def install do
    handlers = %{
      [:phoenix, :endpoint, :stop] => &__MODULE__.phoenix_endpoint_stop/4
    }

    for {key, fun} <- handlers do
      :telemetry.attach({__MODULE__, key}, key, fun, :ok)
    end
  end

  @doc false
  def duration(duration) do
    duration = System.convert_time_unit(duration, :native, :microsecond)

    if duration > 1000 do
      [duration |> div(1000) |> Integer.to_string(), "ms"]
    else
      [Integer.to_string(duration), "µs"]
    end
  end

  defp log_level(nil, _conn), do: :info
  defp log_level(level, _conn) when is_atom(level), do: level

  defp log_level({mod, fun, args}, conn) when is_atom(mod) and is_atom(fun) and is_list(args) do
    apply(mod, fun, [conn | args])
  end

  @doc false
  def phoenix_endpoint_stop(_, %{duration: duration}, %{conn: conn} = metadata, _) do
    case log_level(metadata[:options][:log], conn) do
      false ->
        :ok

      level ->
        Logger.log(
          level,
          fn ->
            %{method: method, request_path: request_path, status: status} = conn
            status = Integer.to_string(status)

            [method, ?\s, request_path, ?\s, status, " in ", duration(duration)]
          end,
          metadata(conn)
        )
    end
  end

  defp metadata(conn) do
    %{method: method, request_path: request_path, status: status} = conn
    status = Integer.to_string(status)

    %{
      method: method,
      request_path: request_path,
      user_agent: extract_user_agent(conn),
      connection_type: connection_type(conn),
      status: status,
      exception: extract_exception(conn)
    }
  end

  defp connection_type(%Plug.Conn{state: :set_chunked}), do: "Chunked"
  defp connection_type(_), do: "Sent"

  defp extract_user_agent(%Plug.Conn{} = conn), do: Plug.Conn.get_req_header(conn, "user-agent")

  defp extract_exception(%Plug.Conn{assigns: %{kind: kind, reason: reason, stack: stack}}),
    do: Exception.format(kind, reason, stack)

  defp extract_exception(_), do: nil
end

In above code, the metadata of log contains a field called exception which is the stacktrace you wanted.

  1. Output the log to a place, such as STDIO, logstash, etc. You can use a custom logger backend for implementing it. In my case, I use ink - print JSON to STDIO. And, related configurations are:
# Configures Elixir's Logger
config :logger,
  backends: [Ink],
  utc_log: true,
  # do not print debug messages in production
  level: :info

config :logger, Ink,
  name: "demo",
  exclude_hostname: true

# Disable default logger of phoenix
config :phoenix, :logger, false
5

Wow this is cool but sounds like overkill! How come stack trace shows up on dev and not production? That means that default logger is capable of outputting it?

6

Did you turn off debug symbols in prod?

7

I don’t know how. Can you point me to the docs on how to do that?

8

UPDATE1: I did more testing on that and discover that I mix release and start app locally I do get stack trace as expected however on my production Ubuntu server I just get application=phoenix request_id=FwQp3A4z_ymkm3sAAAHh [debug] Converted error ArgumentError to 500 response.

I’m using Docker to cross compile the app when I copy it to Ubuntu server where I run it as systemd process.

1 Like
9

Re the ErrorView hack: Yes, it is a hack, but I do get a stack trace. Not necessarily a nicely formatted one, but enough to point me to the problem. (Actually now that I’m trying to reproduce it, it’s also giving me a formatted stack trace, which is weird. Maybe something in my build chain got updated without me noticing, or it depends on exactly from where the error was raised)

Your last update is very curious, since that’s the exact experiment I did to determine that it was the release environment that was failing to log my stack traces. Run in release locally, no traces. (IIRC I had also run it in iex with MIX_ENV=prod and seen stack traces like I wanted)

Re: debug symbols, the best I was able to find was setting strip_beams: false in the release config, documented here, but it didn’t make a difference for me.

10

I noticed that I do get some stack traces. I intentionally made an exception by passing nil to Ecto query and that logs fine on local and production machine. However, Converted error :undef to 500 response which I assume happening due to email validation controller failure doesn’t log anything in production and doesn’t fail on my local system (which is pretty annoying).

So somehow not all exception age getting caught by default which is weird since I use mix gen.auth without pretty much any changes.

Seam like a pretty big flow of Phoenix if it is true.

I didn’t change any debug symbol settings as well.

I will continue to investigate and post some updates.

11

Are you using releases at all?

12

I do use release. This is how I build.

mix local.rebar --force
mix deps.get --only prod
mix deps.compile
mix assets.deploy
mix release

Then I copy content of _build/prod/rel/<my_app> to my server where I run it with systemd.

13

Can you help me to understand where do I put Logger.error(error) to log errors? I don’t understand it from the original post.

14

UPDATE2: It looks like I’m seeing stack trace when I run my release directly with <my_app> start.
However when I run same release as systemd service I no longer see error stack trace.

Here is my systemd config:

[Unit]
Description=Phoenix Codercat Server
After=network.target

[Service]
Environment=MIX_ENV=prod
Environment=PHX_SERVER=true
Environment=DATABASE_URL=xxx
Environment=SECRET_KEY_BASE=xxx
WorkingDirectory=/home/kiko/phx-codercat
Type=simple
Restart=always
RestartSec=1
User=kiko
ExecStart=/home/kiko/phx-codercat/bin/codercat start
ExecStop=/home/kiko/phx-codercat/bin/codercat stop
ExecReload=/home/kiko/phx-codercat/bin/codercat restart

[Install]
WantedBy=multi-user.target

And to see logs I use journalctl -uf <service_name>

I reviews the following relevant post here.

15

In lib/myapp_web/views/error_view.ex:

defmodule MyAppWeb.ErrorView do
  use MyAppWeb, :view

  require Logger

  # If you want to customize a particular status code
  # for a certain format, you may uncomment below.
  def render("500.html", assigns) do
    Logger.error("500 error: #{inspect assigns.reason}, stack: #{inspect assigns.stack}")
    "Internal Server Error."
  end

  # By default, Phoenix returns the status message from
  # the template name. For example, "404.html" becomes
  # "Not Found".
  def template_not_found(template, _assigns) do
    Phoenix.Controller.status_message_from_template(template)
  end
end
2 Likes
16

How you handle logging?

17

I’m not handling it. I’m just using default Phoenix config.

18

Maybe it’s a permissions issue? Do you see more with sudo journalctl -uf <service>?

19

UPDATE3: (3 days latter) I found the root cause of failure in my case. My PHX_URL domain doesn’t match with email service provider that cause error in :create handler for user creation endpoint that was generated with mix phx.auth and hasn’t been modified. Specifically I the error happening in Accounts.deliver_user_confirmation_instructions which not able to deliver email dues to domain not being verified.

I was able to log the error by modifying ErrorView as was suggested to me by @andrewf

What is interesting that the stack trace that I was able to get doesn’t actually provide any useful information about the failure.

15:04:26.993 request_id=FwVpWIEspi5kNgQAAAFR [error] 500 error: 
%UndefinedFunctionError{arity: 4, function: :post, message: nil, module: false, reason: nil},
stack: [{false, :post, [["https://api.mailjet.com/v3.1", "/", "send"], [{"User-Agent", "swoosh/1.7.1"}, {"Authorization", "Basic MjFmNWEyOTE2MjJkZjViOGQ4NDZlYjE5YWMwNGQ4ZDk6Y2QwNDFiOGM5MWU3MzAzNWNhZmIzMDkxYjgzYjc3YmQ="}, {"Content-Type", "application/json"}], "{\"Messages\":[{\"From\":{\"Email\":\"robot@codercat.tk\",\"Name\":\"Draw All The Things!\"},\"Headers\":{},\"Subject\":\"Confirmation instructions\",\"TextPart\":\"\\n==============================\\n\\nHi example@gmail.com,\\n\\nYou can confirm your account by visiting the URL below:\\n\\nhttps://drawallthethings.com/users/confirm/xozIJSnFdNv4hMEnDKMFlR8rMIr5S7x2TT49fTBdkyQ\\n\\nIf you didn't create an account with us, please ignore this.\\n\\n==============================\\n\",\"To\":[{\"Email\":\"example@gmail.com\",\"Name\":\"\"}]}]}",
%Swoosh.Email{assigns: %{}, attachments: [], bcc: [], cc: [], from: {"Draw All The Things!", "robot@codercat.tk"}, headers: %{}, html_body: nil, private: %{}, provider_options: %{}, reply_to: nil, subject: "Confirmation instructions", text_body: "\n==============================\n\nHi example@gmail.com,\n\nYou can confirm your account by visiting the URL below:\n\nhttps://drawallthethings.com/users/confirm/xozIJSnFdNv4hMEnDKMFlR8rMIr5S7x2TT49fTBdkyQ\n\nIf you didn't create an account with us, please ignore this.\n\n==============================\n", to: [{"", "example@gmail.com"}]}], []},
{Swoosh.Adapters.Mailjet, :send_request, 3, [file: 'lib/swoosh/adapters/mailjet.ex', line: 92]},
{Codercat.Mailer, :"-instrument/3-fun-0-", 2, [file: 'lib/codercat/mailer.ex', line: 2]},
{:telemetry, :span, 3, [file: '/home/kiko/phx-codercat-dev/deps/telemetry/src/telemetry.erl', line: 320]}, {Codercat.Accounts.UserNotifier, :deliver, 3, [file: 'lib/codercat/accounts/user_notifier.ex', line: 15]}, 
{CodercatWeb.UserRegistrationController, :create, 2, [file: 'lib/codercat_web/controllers/user_registration_controller.ex', line: 17]},
{CodercatWeb.UserRegistrationController, :action, 2, [file: 'lib/codercat_web/controllers/user_registration_controller.ex', line: 1]},
{CodercatWeb.UserRegistrationController, :phoenix_controller_pipeline, 2, [file: 'lib/codercat_web/controllers/user_registration_controller.ex', line: 1]}]

What I really don’t understand is how come Phoenix framework doesn’t log this error by default. It is not even my custom weird code but rather code generated by Phoenix itself.

2 Likes
20

Thank you, @andrewf, the ErrorView approach that you suggested saved me a bunch of time.

I was seeing Converted error Ecto.Query.CastError to 400 response errors in the log, and Instrumenting template_not_found() to log the call stack was a major time-saver in my investigation. Thank you!

  def template_not_found(template, _assigns) do
    Logger.error("OMG OMG OMG: #{inspect(assigns.reason)}, stack: #{inspect(assigns.stack)}")
    Phoenix.Controller.status_message_from_template(template)
  end
1 Like