whatyouhide / redix

Fast, pipelined, resilient Redis driver for Elixir. 🛍
http://hexdocs.pm/redix
MIT License
1.1k stars 122 forks source link

Redix swallows authentication errors and kills the parent application #236

Closed recursiveGecko closed 1 year ago

recursiveGecko commented 2 years ago

Redix 1.2.0 swallows authentication connection errors when started as part of the supervision tree, terminating the parent application without any details being logged.

application.ex

  @impl true
  def start(_type, _args) do
    children = [
      {Redix, "redis://:INVALID_PASSWORD@localhost"}
    ]

    opts = [strategy: :one_for_one, name: RedixBug.Supervisor]
    Supervisor.start_link(children, opts)
  end

iex

> iex -S mix
Erlang/OTP 25 [erts-13.1] [source] [64-bit] [smp:12:12] [ds:12:12:10] [async-threads:1] [jit:ns]

Compiling 1 file (.ex)
Interactive Elixir (1.14.0) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)> 
10:16:07.089 [notice] Application redix_bug exited: shutdown

The error is reported as expected when Redix is started using start_link/1:

iex(3)> Redix.start_link "redis://:INVALID_PASSWORD@localhost" 
** (EXIT from #PID<0.219.0>) shell process exited with reason: %Redix.Error{message: "ERR AUTH <password> called without any password configured for the default user. Are you sure your configuration is correct?"}
whatyouhide commented 1 year ago

So the reason for this is that when you use start_link, the caller process (the IEx shell in the example above) links directly to the Redix process. When the Redix process exits, your shell exits too and prints the message.

In the supervisor example, the Redix process shuts down correctly but the supervisor restarts it. Then it crashes again, then it restarts. Eventually, the supervisor runs out of max restarts and shuts itself down (with reason shutdown).

There's not much we can do in Redix. Redix itself is behaving correctly IMO: if the password is wrong, we just exit the process with reason %Redix.Error{}.

You can do two things:

  1. Set config :logger, handle_sasl_reports: true in your application. This will show processes going up and down in supervisors. For your example, it'd show something like this:

     13:36:52.447 [error] Process #PID<0.363.0> terminating
     ** (exit) %Redix.Error{message: "ERR AUTH <password> called without any password configured for the default user. Are you sure your configuration is correct?"}
         (stdlib 4.0) gen_statem.erl:1606: :gen_statem.loop_state_callback_result/11
         (stdlib 4.0) proc_lib.erl:240: :proc_lib.init_p_do_apply/3
     Initial Call: Redix.Connection.init/1
     Ancestors: [#PID<0.356.0>, #PID<0.355.0>]
     Message Queue Length: 0
     Messages: []
     Links: [#PID<0.356.0>]
     Dictionary: []
     Trapping Exits: false
     Status: :running
     Heap Size: 610
     Stack Size: 28
     Reductions: 485
    
     13:36:52.447 [error] Child Redix of Supervisor #PID<0.356.0> (Supervisor.Default) terminated
     ** (exit) %Redix.Error{message: "ERR AUTH <password> called without any password configured for the default user. Are you sure your configuration is correct?"}
     Pid: #PID<0.363.0>
     Start Call: Redix.start_link("redis://:INVALID_PASSWORD@localhost")
     Restart: :permanent
     Shutdown: 5000
     Type: :worker
    
     13:36:52.447 [error] Child Redix of Supervisor #PID<0.356.0> (Supervisor.Default) caused shutdown
     ** (exit) :reached_max_restart_intensity
     Start Call: Redix.start_link("redis://:INVALID_PASSWORD@localhost")
     Restart: :permanent
     Shutdown: 5000
     Type: :worker
  2. Use Redix.Telemetry and attach a Telemetry handler to get these logs. For example, you can call [Redix.Telemetry.attach_default_handler()](https://hexdocs.pm/redix/1.2.0/Redix.Telemetry.html#attach_default_handler/0) in your application's start/2 callback, and all events will be logged by default.

Hope this helps!