diff --git a/lib/phoenix/endpoint.ex b/lib/phoenix/endpoint.ex index a923be9a84..e00fc465ee 100644 --- a/lib/phoenix/endpoint.ex +++ b/lib/phoenix/endpoint.ex @@ -635,10 +635,26 @@ defmodule Phoenix.Endpoint do dispatches = for {path, socket, socket_opts} <- sockets, - {path, plug, conn_ast, plug_opts} <- socket_paths(module, path, socket, socket_opts) do + {match_path, plug, conn_ast, plug_opts} <- socket_paths(module, path, socket, socket_opts) do quote do - defp do_socket_dispatch(unquote(path), conn) do - halt(unquote(plug).call(unquote(conn_ast), unquote(Macro.escape(plug_opts)))) + defp do_socket_dispatch(unquote(match_path), conn) do + conn = unquote(conn_ast) + + metadata = %{ + conn: conn, + plug: unquote(plug), + route: unquote("#{path}/#{List.last(match_path)}"), + plug_opts: unquote(Macro.escape(plug_opts)), + path_params: conn.path_params, + user_socket: unquote(socket), + log: unquote(Keyword.get(socket_opts, :log, false)) + } + + :telemetry.span([:phoenix, :socket_dispatch], metadata, fn -> + conn = halt(unquote(plug).call(unquote(conn_ast), unquote(Macro.escape(plug_opts)))) + + {conn, %{metadata | conn: conn}} + end) end end end @@ -980,6 +996,10 @@ defmodule Phoenix.Endpoint do def handle_error(conn, :rate_limit), do: Plug.Conn.send_resp(conn, 429, "Too many requests") + * `:log` - the level to log the socket dispatching under, may be set to false. Defaults to + `false`. To alter the plug log level, please see + https://hexdocs.pm/phoenix/Phoenix.Logger.html#module-dynamic-log-level. + ## Longpoll configuration The following configuration applies only to `:longpoll`: diff --git a/lib/phoenix/logger.ex b/lib/phoenix/logger.ex index 6a19b6a532..196ad1d2cc 100644 --- a/lib/phoenix/logger.ex +++ b/lib/phoenix/logger.ex @@ -48,6 +48,24 @@ defmodule Phoenix.Logger do * Metadata: `%{conn: Plug.Conn.t, route: binary, plug: module, plug_opts: term, path_params: map, pipe_through: [atom], log: Logger.level | false}` * Disable logging: This event is not logged + * `[:phoenix, :socket_dispatch, :start]` - dispatched by `Phoenix.Endpoint` + before dispatching to a matched route + * Measurement: `%{system_time: System.system_time}` + * Metadata: `%{conn: Plug.Conn.t, route: binary, plug: module, plug_opts: term, path_params: map, user_socket: atom, log: Logger.level | false}` + * Disable logging: `socket "/foo", MySocket, log: false` in your endpoint + + * `[:phoenix, :socket_dispatch, :exception]` - dispatched by `Phoenix.Endpoint` + after exceptions on dispatching a route + * Measurement: `%{duration: native_time}` + * Metadata: `%{conn: Plug.Conn.t, kind: :throw | :error | :exit, reason: term(), stacktrace: Exception.stacktrace()}` + * Disable logging: This event is not logged + + * `[:phoenix, :socket_dispatch, :stop]` - dispatched by `Phoenix.Endpoint` + after successfully dispatching a matched route + * Measurement: `%{duration: native_time}` + * Metadata: `%{conn: Plug.Conn.t, route: binary, plug: module, plug_opts: term, path_params: map, user_socket: atom, log: Logger.level | false}` + * Disable logging: This event is not logged + * `[:phoenix, :error_rendered]` - dispatched at the end of an error view being rendered * Measurement: `%{duration: native_time}` * Metadata: `%{conn: Plug.Conn.t, status: Plug.Conn.status, kind: Exception.kind, reason: term, stacktrace: Exception.stacktrace}` @@ -132,6 +150,7 @@ defmodule Phoenix.Logger do [:phoenix, :endpoint, :start] => &__MODULE__.phoenix_endpoint_start/4, [:phoenix, :endpoint, :stop] => &__MODULE__.phoenix_endpoint_stop/4, [:phoenix, :router_dispatch, :start] => &__MODULE__.phoenix_router_dispatch_start/4, + [:phoenix, :socket_dispatch, :start] => &__MODULE__.phoenix_socket_dispatch_start/4, [:phoenix, :error_rendered] => &__MODULE__.phoenix_error_rendered/4, [:phoenix, :socket_connected] => &__MODULE__.phoenix_socket_connected/4, [:phoenix, :channel_joined] => &__MODULE__.phoenix_channel_joined/4, @@ -306,6 +325,23 @@ defmodule Phoenix.Logger do defp params(%Plug.Conn.Unfetched{}), do: "[UNFETCHED]" defp params(params), do: params |> filter_values() |> inspect() + ## Event: [:phoenix, :socket_dispatch, :start] + + @doc false + def phoenix_socket_dispatch_start(_, _, %{log: false}, _), do: :ok + + def phoenix_socket_dispatch_start(_, _, metadata, _) do + %{log: level, conn: conn, plug: plug} = metadata + level = log_level(level, conn) + + Logger.log(level, fn -> + [ + "Processing with ", + inspect(plug) + ] + end) + end + ## Event: [:phoenix, :socket_connected] @doc false diff --git a/test/phoenix/endpoint/endpoint_test.exs b/test/phoenix/endpoint/endpoint_test.exs index 5d8a6579fa..62dc188017 100644 --- a/test/phoenix/endpoint/endpoint_test.exs +++ b/test/phoenix/endpoint/endpoint_test.exs @@ -7,6 +7,8 @@ defmodule Phoenix.Endpoint.EndpointTest do use ExUnit.Case, async: true use RouterHelper + import ExUnit.CaptureLog + @config [ url: [host: {:system, "ENDPOINT_TEST_HOST"}, path: "/api"], static_url: [host: "static.example.com"], @@ -254,6 +256,57 @@ defmodule Phoenix.Endpoint.EndpointTest do :code.delete(__MODULE__.AddressEndpoint) end + @socket_dispatch_start [:phoenix, :socket_dispatch, :start] + @socket_dispatch_stop [:phoenix, :socket_dispatch, :stop] + @socket_dispatch_events [@socket_dispatch_start, @socket_dispatch_stop] + + def message_pid(event, measures, metadata, test_pid) do + send(test_pid, {:telemetry_event, event, {measures, metadata}}) + end + + test "phoenix.socket_dispatch.start and .stop are emitted on sockets", context do + Application.put_env(:phoenix, __MODULE__.SocketEndpoint, static_url: [path: "/static"]) + + defmodule TestSocket do + @behaviour Phoenix.Socket.Transport + def child_spec(_), do: :ignore + def connect(_), do: {:ok, []} + def init(state), do: {:ok, state} + def handle_in(_, state), do: {:ok, state} + def handle_info(_, state), do: {:ok, state} + def terminate(_, _), do: :ok + end + + defmodule SocketEndpoint do + use Phoenix.Endpoint, otp_app: :phoenix + + socket "/custom/:socket_var", TestSocket, websocket: [early_validate_upgrade: false], log: :debug + end + + :telemetry.attach_many(context.test, @socket_dispatch_events, &__MODULE__.message_pid/4, self()) + Logger.enable(self()) + + SocketEndpoint.start_link() + + assert capture_log(fn -> SocketEndpoint.call(conn(:get, "/custom/value/websocket"), []) end) =~ """ + [debug] Processing with Phoenix.Transports.WebSocket + """ + + assert_received {:telemetry_event, [:phoenix, :socket_dispatch, :start], {_, metadata}} + + assert metadata.plug == Phoenix.Transports.WebSocket + assert metadata.route == "/custom/:socket_var/websocket" + assert metadata.path_params == %{"socket_var" => "value"} + assert metadata.log == :debug + assert metadata.user_socket == TestSocket + + assert_received {:telemetry_event, [:phoenix, :socket_dispatch, :stop], {_, _}} + after + :telemetry.detach(context.test) + :code.purge(__MODULE__.SocketEndpoint) + :code.delete(__MODULE__.SocketEndpoint) + end + test "injects pubsub broadcast with configured server" do Endpoint.subscribe("sometopic") some = spawn(fn -> :ok end)