Ecto.NoResultsError not swallowed

[m1ome]

Environment

• Elixir version (elixir -v): Elixir 1.16.0 (compiled with Erlang/OTP 26)
• Phoenix version (mix deps): 1.17.1
• Operating system: MacOS Sonoma 14

Actual behavior

Expect code in controller:

user = Repo.get!(User, id)

Produce a 404 error code and not log any exception.

Expected behavior

Logs and answers with 404 error and crashes GenServer

[error] GenServer #PID<0.6227.0> terminating
** (Ecto.NoResultsError) expected at least one result but got none in query:

from u0 in Waitlist.Models.User,
  where: u0.id == ^"1000000"

    (ecto 3.11.2) lib/ecto/repo/queryable.ex:164: Ecto.Repo.Queryable.one!/3
    (waitlist 0.1.0) lib/waitlist_web/controllers/admin_controller.ex:312: WaitlistWeb.AdminController.show/2
    (waitlist 0.1.0) lib/waitlist_web/controllers/admin_controller.ex:1: WaitlistWeb.AdminController.action/2
    (waitlist 0.1.0) lib/waitlist_web/controllers/admin_controller.ex:1: WaitlistWeb.AdminController.phoenix_controller_pipeline/2
    (phoenix 1.7.11) lib/phoenix/router.ex:484: Phoenix.Router.__call__/5
    (waitlist 0.1.0) lib/waitlist_web/endpoint.ex:1: WaitlistWeb.Endpoint.plug_builder_call/2
    (waitlist 0.1.0) deps/plug/lib/plug/debugger.ex:136: WaitlistWeb.Endpoint."call (overridable 3)"/2
    (waitlist 0.1.0) lib/waitlist_web/endpoint.ex:1: WaitlistWeb.Endpoint.call/2
    (phoenix 1.7.11) lib/phoenix/endpoint/sync_code_reload_plug.ex:22: Phoenix.Endpoint.SyncCodeReloadPlug.do_call/4
    (bandit 1.4.1) lib/bandit/pipeline.ex:150: Bandit.Pipeline.call_plug!/2
    (bandit 1.4.1) lib/bandit/pipeline.ex:36: Bandit.Pipeline.run/4
    (bandit 1.4.1) lib/bandit/http1/handler.ex:12: Bandit.HTTP1.Handler.handle_data/3
    (bandit 1.4.1) lib/bandit/delegating_handler.ex:18: Bandit.DelegatingHandler.handle_data/3
    (bandit 1.4.1) /Users/w1n2k/Work/Onmi/onmi_waitlist/waitlist/deps/thousand_island/lib/thousand_island/handler.ex:411: Bandit.DelegatingHandler.handle_continue/2
    (stdlib 5.2) gen_server.erl:1085: :gen_server.try_handle_continue/3
    (stdlib 5.2) gen_server.erl:995: :gen_server.loop/7
    (stdlib 5.2) proc_lib.erl:241: :proc_lib.init_p_do_apply/3
Last message: {:continue, :handle_connection}
State: {%ThousandIsland.Socket{socket: #Port<0.35>, transport_module: ThousandIsland.Transports.TCP, read_timeout: 60000, silent_terminate_on_error: false, span: %ThousandIsland.Telemetry{span_name: :connection, telemetry_span_context: #Reference<0.3165843089.4253548547.188374>, start_time: -576460731388243250, start_metadata: %{telemetry_span_context: #Reference<0.3165843089.4253548547.188374>, remote_address: {127, 0, 0, 1}, remote_port: 53420, parent_telemetry_span_context: #Reference<0.3165843089.4253548547.188228>}}}, %{opts: %{http: [], http_1: [], http_2: [], websocket: []}, plug: {Phoenix.Endpoint.SyncCodeReloadPlug, {WaitlistWeb.Endpoint, []}}, http_1_enabled: true, http_2_enabled: true, handler_module: Bandit.InitialHandler}}

[chrismccord]

We need more information. Is this in dev with debug_errors set to true (which does not wrap errors)? Can you share your controller which does the Repo.get!? Thanks!

[m1ome]

dev.exs configuration

config :waitlist, WaitlistWeb.Endpoint,
  http: [ip: {127, 0, 0, 1}, port: 4000],
  check_origin: false,
  code_reloader: false,
  debug_errors: false,

Simplified controller code

defmodule WaitlistWeb.AdminController do
  use WaitlistWeb, :controller

  import Ecto.Query

  alias Waitlist.Repo
  alias Waitlist.Models.User

  def show(conn, %{"id" => id}) do
    user = Repo.get!(User, id)
    render(conn, :user, user: user)
  end
end

Double checked with this one and still have error logged with a GenServer crash.
Btw regular 404 like with a missing route seems fine (and same with insert! with a conflict)

[m1ome]

@chrismccord any news? Maybe it will be helpful if i can provide a working demo for all this?

[aaronrenner]

I just tried upgrading to Bandit and I'm noticing that exceptions implementing the Plug.Exception protocol like Ecto.NoResultsError are erroring loudly when previously I believe they were suppressed.

Here's a sample app that recreates the issue even with debug_errors: false: https://github.com/aaronrenner/phx_no_results_error_demo

[info] GET /books/1
[debug] Processing with SampleAppWeb.BookController.show/2
  Parameters: %{"id" => "1"}
  Pipelines: [:browser]
[debug] QUERY OK source="books" db=0.4ms queue=0.5ms idle=1912.5ms
SELECT b0."id", b0."description", b0."title", b0."inserted_at", b0."updated_at" FROM "books" AS b0 WHERE (b0."id" = $1) [1]
↳ SampleAppWeb.BookController.show/2, at: lib/sample_app_web/controllers/book_controller.ex:30
[info] Sent 404 in 19ms
[debug] Converted error Ecto.NoResultsError to 404 response
[error] GenServer #PID<0.838.0> terminating
** (Ecto.NoResultsError) expected at least one result but got none in query:

from b0 in SampleApp.Bookstore.Book,
  where: b0.id == ^"1"

    (ecto 3.11.2) lib/ecto/repo/queryable.ex:164: Ecto.Repo.Queryable.one!/3
    (sample_app 0.1.0) lib/sample_app_web/controllers/book_controller.ex:30: SampleAppWeb.BookController.show/2
    (sample_app 0.1.0) lib/sample_app_web/controllers/book_controller.ex:1: SampleAppWeb.BookController.action/2
    (sample_app 0.1.0) lib/sample_app_web/controllers/book_controller.ex:1: SampleAppWeb.BookController.phoenix_controller_pipeline/2
    (phoenix 1.7.12) lib/phoenix/router.ex:484: Phoenix.Router.__call__/5
    (sample_app 0.1.0) lib/sample_app_web/endpoint.ex:1: SampleAppWeb.Endpoint.plug_builder_call/2
    (sample_app 0.1.0) lib/sample_app_web/endpoint.ex:1: SampleAppWeb.Endpoint.call/2
    (phoenix 1.7.12) lib/phoenix/endpoint/sync_code_reload_plug.ex:22: Phoenix.Endpoint.SyncCodeReloadPlug.do_call/4
    (bandit 1.4.2) lib/bandit/pipeline.ex:150: Bandit.Pipeline.call_plug!/2
    (bandit 1.4.2) lib/bandit/pipeline.ex:36: Bandit.Pipeline.run/4
    (bandit 1.4.2) lib/bandit/http1/handler.ex:12: Bandit.HTTP1.Handler.handle_data/3
    (bandit 1.4.2) lib/bandit/delegating_handler.ex:18: Bandit.DelegatingHandler.handle_data/3
    (bandit 1.4.2) /Users/aaronrenner/projects/sample_app/deps/thousand_island/lib/thousand_island/handler.ex:379: Bandit.DelegatingHandler.handle_info/2
    (stdlib 4.3) gen_server.erl:1123: :gen_server.try_dispatch/4
    (stdlib 4.3) gen_server.erl:1200: :gen_server.handle_msg/6
    (stdlib 4.3) proc_lib.erl:240: :proc_lib.init_p_do_apply/3
Last message: {:tcp, #Port<0.23>, "GET /books/1 HTTP/1.1\r\nHost: localhost:4000\r\nUser-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:124.0) Gecko/20100101 Firefox/124.0\r\nAccept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8\r\nAccept-Language: en-US,en;q=0.5\r\nAccept-Encoding: gzip, deflate, br\r\nConnection: keep-alive\r\nCookie: user_data=eyJoZXhfY29sb3IiOiIjNjBBNUZBIiwibmFtZSI6bnVsbH0=; _sched_cookie=QTEyOEdDTQ.MF98ZMWqY4TFxeLM9q22Qz8nBOKNEFKo_xhuypMNxe_VP3NssaJjWLQGqJo.hjbBb9I0nroBwBl-.bmIcvgWdFA_lV-iQ5oO0v-iIqrMrKv6LvuLc_5LLVKJg1CvjGBnqH5t1-7OBnEjIHA61U-f_jpx0A_eG7RpDPjh-pnPUqTjQwiFOfh2g8YW7H4miNwT6CF5yJA7RcofOBE0OnPvXMiWuVG7A16Oyt4lwo6LTKSHEhXQpEFtLYQ9I3A723inzkCtHb0DE6rwUh7WSjzwJX4cyqfctg-LW3DyTKenj5fmfxPGqo4sYk90EvPZ38MakXdrEKNRUSDja4P5IjdjklXOYer4izWsJT0wd3i0OC9FzoR-7H8rHU-PFXW7MSNWxg0mOzmNWCWRq2qbSz4a1YL9FZ1e8g-JacKNisoi-qGIim5JYw3Ra0IPbGc6KPAYNR-ylRzflGzFAG6nC_ymOoWvy9TurLECSKAfrRzHgTiBeJezsFr_lSJgY47-RUphwEzNQBPi3ViORokdD-wGJ5tw1y9OH8PsoMGgOpFe7haoQ-4k93QEgxPZVnJ0vMdgQQhtOZqB9GOjut4ck9yJu46tVhM69bSStKf2rXfFf0pzUqt8I7GmC5ChIKWAWlAMTO7DT79I2jZmj5_wD5s32yBy7NHhU7VXYEj9Up-aW0YfVmuARlptTLGTqa5IMk_FIKqnTWl1jKLbe2WaYcLCYWBZaom3cZ3Sw-Eduw1tEcXjorr8_hyLFPfFvezk0Ketl9_PMy2LIukRctRpkoVf6N78h3WYLe0Q09Vjf-Zr-_WLqjSsmIsc34yg.cJv7792VXu1lbPgH9oQfyA; AMP=JTdCJTIyb3B0T3V0JTIyJTNBZmFsc2UlMkMlMjJkZXZpY2VJZCUyMiUzQSUyMjIzNzRjMzgzLTJkMjktNGNkNS1hN2UyLTgyNTNiMjBiNmJlZCUyMiUyQyUyMmxhc3RFdmVudFRpbWUlMjIlM0ExNzEyODcxNDMxMjU1JTJDJTIyc2Vzc2lvbkl"}
State: {%ThousandIsland.Socket{socket: #Port<0.23>, transport_module: ThousandIsland.Transports.TCP, read_timeout: 60000, silent_terminate_on_error: false, span: %ThousandIsland.Telemetry{span_name: :connection, telemetry_span_context: #Reference<0.3539481425.3026714630.127782>, start_time: -576460738118843053, start_metadata: %{parent_telemetry_span_context: #Reference<0.3539481425.3026714628.126592>, remote_address: {127, 0, 0, 1}, remote_port: 53317, telemetry_span_context: #Reference<0.3539481425.3026714630.127782>}}}, %{handler_module: Bandit.HTTP1.Handler, http_1_enabled: true, http_2_enabled: true, opts: %{http: [], http_1: [], http_2: [], websocket: []}, plug: {Phoenix.Endpoint.SyncCodeReloadPlug, {SampleAppWeb.Endpoint, []}}, requests_processed: 8}}

Ideally I'd expect to see just the Sent 404 in 19ms log message. I did see that we can make thousand_island swallow all errors using thousand_island_config: [silent_terminate_on_error: true], but I'm not sure if that's the recommended way to do this.

mtrudel/bandit#252 (comment)

[mtrudel]

I've got a nice clean solution for this coming in the next Bandit; working on it today and should have it out this weekend.

[mtrudel]

Bandit PR up for review that takes Plug.Exception.status/1 into consideration when handling exceptions & adds a log_exceptions_with_status_codes config option (defaulting to 500..599). This should shut Bandit up for non 500 errors by default

@aaronrenner @m1ome any chance you can test with {:bandit, github: "mtrudel/bandit", branch: "plug_exception_awareness"} and see if it fixes your issue?

[aaronrenner]

Thanks @mtrudel! I just tested this in the sample app and at work and I can confirm it fixes the issue!

I really appreciate your help! ❤️

[mtrudel]

Bandit fix just went out as 1.5.0

[m1ome]

Thanks @mtrudel. Awesome job!

[m1ome]

I will close this one, it's fixed in bandit 1.5.0, thanks to @mtrudel