Allow WebConsoleLogger to shutdown cleanly

[axelson]

Before this commit when executing a clean shutdown via System.stop() errors would be printed to the console: Logger - error: {Logger - error: removed_failing_handler,'Elixir.Phoenix.LiveReloader.WebConsoleLogger'}

(plus about 7 errors at the debug level)

This is avoided by controlling the application startup and shutdown via a new WebConsoleLoggerInitializer GenServer that runs detach_logger before the Phoenix.LiveReloader.WebConsoleLoggerRegistry is shutdown.

This is important because with all the error messages it is hard to tell if your phoenix-based application is shutting down cleanly.

This can be tested by starting a phoenix application that uses :phoenix_live_reload with iex -S mix phx.server and then running System.stop. No error logs from :phoenix_live_reload should be printed.

Here's the logs that I was seeing without this change (they're a little hard to read since they got interspersed with each other):

Logger - error: {Logger - error: removed_failing_handler,'Elixir.Phoenix.LiveReloader.WebConsoleLogger'}
{removed_failing_handler,'Elixir.Phoenix.LiveReloader.WebConsoleLogger'}
Logger - error: {remoLogger - error: ved_failing_handler,'Elixir.Phoenix.LiveReloader.WebConsoleLoLogger - error: gger10:28:01.177 [info] Postgrex.Protocol (#PID<0.380.0>) missed message: {:EXIT, #PID<0.392.0>, :shutdown}
Logger - error:  }
{remov10:28:01.177 [info] Postgrex.Protocol (#PID<0.383.0>) missed message: {:EXIT, #PID<0.392.0>, :shutdown}
ed_failing_handler,'Elixir.Phoenix.LiveReloader.WebConsoleLogger'}
10:28:01.177 [info] Postgrex.Protocol (#PID<0.378.0>) missed message: {:EXIT, #PID<0.392.0>, :shutdown}
{10:28:01.177 [info] Postgrex.Protocol (#PID<0.379.0>) missed message: {:EXIT, #PID<0.392.0>, :shutdown}
removed_failing_handler,'Elixir.Phoenix.LiveReloader.WebConsoleLogger'}
{removed_failing_handler,'Elixir.Phoenix.LiveReloader.WebConsoleLogger'}
10:28:01.177 [info] Postgrex.Protocol (#PID<0.382.0>) missed message: {:EXIT, #PID<0.392.0>, :shutdown}
{removed_10:28:01.177 [info] Postgrex.Protocol (#PID<0.377.0>) missed message: {:EXIT, #PID<0.392.0>, :shutdown}
failing_handler,'Elixir.Phoenix.LiveReloader.WebConsoleLogger'}
10:28:01.177 [info] Postgrex.Protocol (#PID<0.381.0>) missed message: {:EXIT, #PID<0.392.0>, :shutdown}
10:28:01.180 [debug] [logger: :removed_failing_handler, handler: {Phoenix.LiveReloader.WebConsoleLogger, Phoenix.LiveReloader.WebConsoleLogger}, log_event: %{meta: %{line: 347, pid: #PID<0.381.0>, time: 1714249681177350, file: ~c"lib/db_connection/connection.ex", gl: #PID<0.239.0>, domain: [:elixir], application: :db_connection, mfa: {DBConnection.Connection, :handle_event, 4}}, msg: {:string, ["Postgrex.Protocol", 32, 40, "#PID<0.381.0>", ") missed message: " | "{:EXIT, #PID<0.392.0>, :shutdown}"]}, level: :info}, config: %{id: Phoenix.LiveReloader.WebConsoleLogger, module: Phoenix.LiveReloader.WebConsoleLogger, formatter: {Logger.Formatter, %Logger.Formatter{template: [:time, " [", :level, "] ", :message, "\n"], truncate: 8096, metadata: [:request_id], colors: %{error: :red, enabled: false, info: :normal, warning: :yellow, debug: :cyan, notice: :normal, alert: :red, critical: :red, emergency: :red}, utc_log?: false}}}, reason: {:error, %ArgumentError{message: "unknown registry: Phoenix.LiveReloader.WebConsoleLoggerRegistry"}, [{Registry, :key_info!, 1, [file: ~c"lib/registry.ex", line: 1400]}, {Registry, :dispatch, 4, [file: ~c"lib/registry.ex", line: 478]}]}]
10:28:01.180 [debug] [logger: :removed_failing_handler, handler: {Phoenix.LiveReloader.WebConsoleLogger, Phoenix.LiveReloader.WebConsoleLogger}, log_event: %{meta: %{line: 347, pid: #PID<0.382.0>, time: 1714249681177256, file: ~c"lib/db_connection/connection.ex", gl: #PID<0.239.0>, domain: [:elixir], application: :db_connection, mfa: {DBConnection.Connection, :handle_event, 4}}, msg: {:string, ["Postgrex.Protocol", 32, 40, "#PID<0.382.0>", ") missed message: " | "{:EXIT, #PID<0.392.0>, :shutdown}"]}, level: :info}, config: %{id: Phoenix.LiveReloader.WebConsoleLogger, module: Phoenix.LiveReloader.WebConsoleLogger, formatter: {Logger.Formatter, %Logger.Formatter{template: [:time, " [", :level, "] ", :message, "\n"], truncate: 8096, metadata: [:request_id], colors: %{error: :red, enabled: false, info: :normal, warning: :yellow, debug: :cyan, notice: :normal, alert: :red, critical: :red, emergency: :red}, utc_log?: false}}}, reason: {:error, %ArgumentError{message: "unknown registry: Phoenix.LiveReloader.WebConsoleLoggerRegistry"}, [{Registry, :key_info!, 1, [file: ~c"lib/registry.ex", line: 1400]}, {Registry, :dispatch, 4, [file: ~c"lib/registry.ex", line: 478]}]}]
10:28:01.180 [debug] [logger: :removed_failing_handler, handler: {Phoenix.LiveReloader.WebConsoleLogger, Phoenix.LiveReloader.WebConsoleLogger}, log_event: %{meta: %{line: 347, pid: #PID<0.378.0>, time: 1714249681177335, file: ~c"lib/db_connection/connection.ex", gl: #PID<0.239.0>, domain: [:elixir], application: :db_connection, mfa: {DBConnection.Connection, :handle_event, 4}}, msg: {:string, ["Postgrex.Protocol", 32, 40, "#PID<0.378.0>", ") missed message: " | "{:EXIT, #PID<0.392.0>, :shutdown}"]}, level: :info}, config: %{id: Phoenix.LiveReloader.WebConsoleLogger, module: Phoenix.LiveReloader.WebConsoleLogger, formatter: {Logger.Formatter, %Logger.Formatter{template: [:time, " [", :level, "] ", :message, "\n"], truncate: 8096, metadata: [:request_id], colors: %{error: :red, enabled: false, info: :normal, warning: :yellow, debug: :cyan, notice: :normal, alert: :red, critical: :red, emergency: :red}, utc_log?: false}}}, reason: {:error, %ArgumentError{message: "unknown registry: Phoenix.LiveReloader.WebConsoleLoggerRegistry"}, [{Registry, :key_info!, 1, [file: ~c"lib/registry.ex", line: 1400]}, {Registry, :dispatch, 4, [file: ~c"lib/registry.ex", line: 478]}]}]
10:28:01.180 [debug] [logger: :removed_failing_handler, handler: {Phoenix.LiveReloader.WebConsoleLogger, Phoenix.LiveReloader.WebConsoleLogger}, log_event: %{meta: %{line: 347, pid: #PID<0.377.0>, time: 1714249681177253, file: ~c"lib/db_connection/connection.ex", gl: #PID<0.239.0>, domain: [:elixir], application: :db_connection, mfa: {DBConnection.Connection, :handle_event, 4}}, msg: {:string, ["Postgrex.Protocol", 32, 40, "#PID<0.377.0>", ") missed message: " | "{:EXIT, #PID<0.392.0>, :shutdown}"]}, level: :info}, config: %{id: Phoenix.LiveReloader.WebConsoleLogger, module: Phoenix.LiveReloader.WebConsoleLogger, formatter: {Logger.Formatter, %Logger.Formatter{template: [:time, " [", :level, "] ", :message, "\n"], truncate: 8096, metadata: [:request_id], colors: %{error: :red, enabled: false, info: :normal, warning: :yellow, debug: :cyan, notice: :normal, alert: :red, critical: :red, emergency: :red}, utc_log?: false}}}, reason: {:error, %ArgumentError{message: "unknown registry: Phoenix.LiveReloader.WebConsoleLoggerRegistry"}, [{Registry, :key_info!, 1, [file: ~c"lib/registry.ex", line: 1400]}, {Registry, :dispatch, 4, [file: ~c"lib/registry.ex", line: 478]}]}]
10:28:01.180 [debug] [logger: :removed_failing_handler, handler: {Phoenix.LiveReloader.WebConsoleLogger, Phoenix.LiveReloader.WebConsoleLogger}, log_event: %{meta: %{line: 347, pid: #PID<0.379.0>, time: 1714249681177389, file: ~c"lib/db_connection/connection.ex", gl: #PID<0.239.0>, domain: [:elixir], application: :db_connection, mfa: {DBConnection.Connection, :handle_event, 4}}, msg: {:string, ["Postgrex.Protocol", 32, 40, "#PID<0.379.0>", ") missed message: " | "{:EXIT, #PID<0.392.0>, :shutdown}"]}, level: :info}, config: %{id: Phoenix.LiveReloader.WebConsoleLogger, module: Phoenix.LiveReloader.WebConsoleLogger, formatter: {Logger.Formatter, %Logger.Formatter{template: [:time, " [", :level, "] ", :message, "\n"], truncate: 8096, metadata: [:request_id], colors: %{error: :red, enabled: false, info: :normal, warning: :yellow, debug: :cyan, notice: :normal, alert: :red, critical: :red, emergency: :red}, utc_log?: false}}}, reason: {:error, %ArgumentError{message: "unknown registry: Phoenix.LiveReloader.WebConsoleLoggerRegistry"}, [{Registry, :key_info!, 1, [file: ~c"lib/registry.ex", line: 1400]}, {Registry, :dispatch, 4, [file: ~c"lib/registry.ex", line: 478]}]}]
10:28:01.179 [debug] [logger: :removed_failing_handler, handler: {Phoenix.LiveReloader.WebConsoleLogger, Phoenix.LiveReloader.WebConsoleLogger}, log_event: %{meta: %{line: 347, pid: #PID<0.380.0>, time: 1714249681177279, file: ~c"lib/db_connection/connection.ex", gl: #PID<0.239.0>, domain: [:elixir], application: :db_connection, mfa: {DBConnection.Connection, :handle_event, 4}}, msg: {:string, ["Postgrex.Protocol", 32, 40, "#PID<0.380.0>", ") missed message: " | "{:EXIT, #PID<0.392.0>, :shutdown}"]}, level: :info}, config: %{id: Phoenix.LiveReloader.WebConsoleLogger, module: Phoenix.LiveReloader.WebConsoleLogger, formatter: {Logger.Formatter, %Logger.Formatter{template: [:time, " [", :level, "] ", :message, "\n"], truncate: 8096, metadata: [:request_id], colors: %{error: :red, enabled: false, info: :normal, warning: :yellow, debug: :cyan, notice: :normal, alert: :red, critical: :red, emergency: :red}, utc_log?: false}}}, reason: {:error, %ArgumentError{message: "unknown registry: Phoenix.LiveReloader.WebConsoleLoggerRegistry"}, [{Registry, :key_info!, 1, [file: ~c"lib/registry.ex", line: 1400]}, {Registry, :dispatch, 4, [file: ~c"lib/registry.ex", line: 478]}]}]
10:28:01.179 [debug] [logger: :removed_failing_handler, handler: {Phoenix.LiveReloader.WebConsoleLogger, Phoenix.LiveReloader.WebConsoleLogger}, log_event: %{meta: %{line: 347, pid: #PID<0.383.0>, time: 1714249681177276, file: ~c"lib/db_connection/connection.ex", gl: #PID<0.239.0>, domain: [:elixir], application: :db_connection, mfa: {DBConnection.Connection, :handle_event, 4}}, msg: {:string, ["Postgrex.Protocol", 32, 40, "#PID<0.383.0>", ") missed message: " | "{:EXIT, #PID<0.392.0>, :shutdown}"]}, level: :info}, config: %{id: Phoenix.LiveReloader.WebConsoleLogger, module: Phoenix.LiveReloader.WebConsoleLogger, formatter: {Logger.Formatter, %Logger.Formatter{template: [:time, " [", :level, "] ", :message, "\n"], truncate: 8096, metadata: [:request_id], colors: %{error: :red, enabled: false, info: :normal, warning: :yellow, debug: :cyan, notice: :normal, alert: :red, critical: :red, emergency: :red}, utc_log?: false}}}, reason: {:error, %ArgumentError{message: "unknown registry: Phoenix.LiveReloader.WebConsoleLoggerRegistry"}, [{Registry, :key_info!, 1, [file: ~c"lib/registry.ex", line: 1400]}, {Registry, :dispatch, 4, [file: ~c"lib/registry.ex", line: 478]}]}]

[josevalim]

Nice find! Do you think we could the Application.stop callback instead? Or is that too late?

[axelson]

Application.stop would be too late, although Application.prep_stop could work. And I tried making that change in dbb27be2671b9119e257169371f052a12e4ab093. However, after making that change and thinking about it I realized that there is also a race condition on startup. If a log message comes in between attach_logger() and the Registry starting up then the WebConsoleLogger handler will fail and become detached. Here's a sequence diagram illustrating that (you can probably understand without the sequence diagram but it's good practice for me to create one and maybe it'll help someone in the future):

sequenceDiagram
    participant LoggerHandler
    participant Registry
    participant OtherDep

    LoggerHandler->>LoggerHandler: attach
    OtherDep->>LoggerHandler: log message
    LoggerHandler->>Registry: Registry.dispatch
    Note left of LoggerHandler: Handler fails with<br/>{removed_failing_handler,'Elixir.Phoenix.LiveReloader.WebConsoleLogger'}<br />This happens because the Registry has not yet been started
    Registry->>Registry: startup

If we instead move all the startup and initialization into the supervision tree then we can ensure that on startup the handler is not attached before the Registry starts and also ensure that the handler is detached before the Registry stops. Here's a sequence diagram of that:

sequenceDiagram
    participant LoggerHandler
    participant Registry
    participant OtherDep

    Registry->>Registry: startup
    LoggerHandler->>LoggerHandler: attach
    OtherDep->>LoggerHandler: log message
    LoggerHandler->>Registry: Registry.dispatch
    Note right of Registry: success!

While we could keep the handler_detach call in application.ex to me it makes more sense to keep the attach and detach both in the same module because then it's easier to follow and understand the flow. In 82ab0607832fdd37aa611617a763eadbb62cce67 I've moved the attach/detach logic back into the supervision tree but moved the GenServer logic into WebConsoleLogger itself.

[josevalim]

:green_heart: :blue_heart: :purple_heart: :yellow_heart: :heart: