kif

No stack trace in production log

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.

19 comments

/phoenix #logging #production #deployment #error-handling

6 4190 19

2022-09-13 08:01:04 UTC

Marked As Solved

andrewf

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

Post #15

Also Liked

kif

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.

Post #19

kif

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.

Post #8

markmark206

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

Post #20