Error logging and stack traces in release vs IEx

Hello, possibly dumb question here. I’m deploying my phoenix app with a release. I’ve found that in production, for some (all?) errors, I don’t see a stack trace (or any detail at all) on stdout. I thought it might be a systemd problem, but it turns out that any time I run the app as a release, the stack trace is not printed, whereas in IEx on my local dev machine, it is.

To replicate the issue, I injected a BadMatch error in one of my templates. Running it with iex -S mix phx.server and exercising the “bug” on my dev machine (Fedora FWIW), I get the following console output:

15:26:52.021 request_id=Fv2qoZqEAPV4uO4AAADi [info] Sent 500 in 9ms
15:26:52.021 request_id=Fv2qoZqEAPV4uO4AAADi [debug] Converted error {:badmatch, {:error, "hi"}} to 500 response
15:26:52.022 [error] #PID<0.772.0> running JotWeb.Endpoint (connection #PID<0.771.0>, stream id 1) terminated
Server: localhost:4000 (http)
Request: GET /users/settings?request_logger=SFMyNTY.g2gDbQAAAAQtNGt1bgYAPfcYuYEBYgABUYA.GBfMET2R40_SNjDu0eC-a1acKXxITltZS1QGwGLKyCs
** (exit) an exception was raised:
    ** (MatchError) no match of right hand side value: {:error, "hi"}
        (jot 0.1.0) lib/jot_web/templates/user_settings/edit.html.heex:15: anonymous fn/2 in JotWeb.UserSettingsView."edit.html"/1
        (phoenix_live_view 0.17.9) lib/phoenix_live_view/engine.ex:124: Phoenix.HTML.Safe.Phoenix.LiveView.Rendered.to_iodata/1
(yada blah, snip)

Running the same project as a release (Debian production clone), I only get the first two log messages.

07:46:48.765 request_id=Fv2k9K6WIU86lpIAAAHB [info] Sent 500 in 15ms
07:46:48.765 request_id=Fv2k9K6WIU86lpIAAAHB [debug] Converted error {:badmatch, {:error, "hi"}} to 500 response

(crickets)

So I’d like to understand why this is, and figure out how to get stack traces from production crashes. My hazy guess, after a bit of investigation, is that Plug/Phoenix logs the errors I do see via telemetry, sends 500, then rethrows. IEx sees the rethrow as an unhandled exception, and helpfully prints it. The release runtime, uh, doesn’t.

I’m sure there are docs that explain this well enough, but my google-fu is inadequate to find them, so I’d love pointers. I’m also open to creative, low-effort ways to get better production error messages; I’m thinking about how to do really robust logging, but not too picky at this stage, as I’m at extreme risk of letting perfect be the enemy of good enough.

Thanks!

2 Likes

Hi, I think it is exactly this one :undef to 500 response when running tests - #11 by teatimes

My own logger config for prod:

config :logger, :console,
  format: "$time $metadata[$level] $message\n",
  metadata: [:application, :registered_name, :request_id]

config :logger, level: :info

You could store logs in a file… with this package

I have a hard time figuring out exactly what that person wanted (I think they were trying to see fewer or different logs, not more of them like me), but their trick of using Logger.error in the error view helped, so at least my hair’s not on fire anymore. I had already set my log level to debug, just to see if there was anything else at all I could find out about the original error I was having.

I could be wrong, but I’m pretty sure my problem is that Logger isn’t even seeing the messages I’m interested in, so I don’t think changing the backend would help. In prod, I’m just doing the default systemd thing of having stdout be the main log and letting journald or whatever take care of persisting it.