diff --git a/guides/endpoint.md b/guides/endpoint.md index ea3c7ca6a5..4ef96fae1d 100644 --- a/guides/endpoint.md +++ b/guides/endpoint.md @@ -65,11 +65,11 @@ if code_reloading? do end ``` -[Plug.RequestId](https://hexdocs.pm/plug/Plug.RequestId.html) generates a unique id for each request and [Plug.Logger](https://hexdocs.pm/plug/Plug.Logger.html) logs the request path, status code and request time by default. +[Plug.RequestId](https://hexdocs.pm/plug/Plug.RequestId.html) generates a unique id for each request and [Plug.Telemetry](https://hexdocs.pm/plug/Plug.Telemetry.html) adds instrumentation points so Phoenix can log the request path, status code and request time by default. ```elixir plug Plug.RequestId -plug Plug.Logger +plug Plug.Telemetry, event_prefix: [:phoenix, :endpoint] ``` [Plug.Session](https://hexdocs.pm/plug/Plug.Session.html) handles the session cookies and session stores. diff --git a/installer/templates/phx_web/endpoint.ex b/installer/templates/phx_web/endpoint.ex index 4da37b5ea5..4ebc796ec9 100644 --- a/installer/templates/phx_web/endpoint.ex +++ b/installer/templates/phx_web/endpoint.ex @@ -24,7 +24,7 @@ defmodule <%= endpoint_module %> do end plug Plug.RequestId - plug Plug.Logger + plug Plug.Telemetry, event_prefix: [:phoenix, :endpoint] plug Plug.Parsers, parsers: [:urlencoded, :multipart, :json], diff --git a/lib/phoenix.ex b/lib/phoenix.ex index 7d9ba5ccd1..4f91a081e0 100644 --- a/lib/phoenix.ex +++ b/lib/phoenix.ex @@ -44,6 +44,8 @@ defmodule Phoenix do :erlang.system_flag(:backtrace_depth, stacktrace_depth) end + Phoenix.Logger.install() + # Start the supervision tree import Supervisor.Spec diff --git a/lib/phoenix/channel/server.ex b/lib/phoenix/channel/server.ex index 9cd93323bb..66afdd9be2 100644 --- a/lib/phoenix/channel/server.ex +++ b/lib/phoenix/channel/server.ex @@ -32,9 +32,7 @@ defmodule Phoenix.Channel.Server do ref = make_ref() from = {self(), ref} - # TODO: When we migrate to DynamicSupervisor, we will start - # {channel, {payload, from, socket}} and have its child spec - # point back to this module start link. + # TODO: Migrate to DynamicSupervisor and invoke the channel child_spec. args = [channel, {payload, from, socket}] case PoolSupervisor.start_child(socket.endpoint, socket.handler, from, args) do @@ -252,29 +250,13 @@ defmodule Phoenix.Channel.Server do private: Map.merge(channel.__socket__(:private), private) } - case channel_join(socket, channel, topic, auth_payload) do - {:ok, socket} -> - init_info(socket, channel, topic, %{}, from) - - {:ok, reply, socket} -> - init_info(socket, channel, topic, reply, from) - - {:error, reply} -> - log_join(socket, topic, fn -> "Replied #{topic} :error" end) - GenServer.reply(from, {:error, reply}) - {:stop, :shutdown, socket} - - other -> - raise """ - channel #{inspect(socket.channel)}.join/3 is expected to return one of: - - {:ok, Socket.t} | - {:ok, reply :: map, Socket.t} | - {:error, reply :: map} - - got #{inspect(other)} - """ - end + start = System.monotonic_time() + {reply, state} = channel_join(channel, topic, auth_payload, socket) + duration = System.monotonic_time() - start + metadata = %{params: auth_payload, socket: socket, result: elem(reply, 0)} + :telemetry.execute([:phoenix, :channel_joined], %{duration: duration}, metadata) + GenServer.reply(from, reply) + state end def handle_info(%Message{topic: topic, event: "phx_leave", ref: ref}, %{topic: topic} = socket) do @@ -285,13 +267,12 @@ defmodule Phoenix.Channel.Server do %Message{topic: topic, event: event, payload: payload, ref: ref}, %{topic: topic} = socket ) do - runtime = %{ref: ref, event: event, params: payload, socket: socket} - - Phoenix.Endpoint.instrument(socket, :phoenix_channel_receive, runtime, fn -> - event - |> socket.channel.handle_in(payload, put_in(socket.ref, ref)) - |> handle_in() - end) + start = System.monotonic_time() + result = socket.channel.handle_in(event, payload, put_in(socket.ref, ref)) + duration = System.monotonic_time() - start + metadata = %{ref: ref, event: event, params: payload, socket: socket} + :telemetry.execute([:phoenix, :channel_handled_in], %{duration: duration}, metadata) + handle_in(result) end def handle_info( @@ -379,29 +360,40 @@ defmodule Phoenix.Channel.Server do ## Joins - defp channel_join(socket, channel, topic, auth_payload) do - instrument = %{params: auth_payload, socket: socket} + defp channel_join(channel, topic, auth_payload, socket) do + case channel.join(topic, auth_payload, socket) do + {:ok, socket} -> + {{:ok, %{}}, init_join(socket, channel, topic)} - Phoenix.Endpoint.instrument(socket, :phoenix_channel_join, instrument, fn -> - channel.join(topic, auth_payload, socket) - end) + {:ok, reply, socket} -> + {{:ok, reply}, init_join(socket, channel, topic)} + + {:error, reply} -> + {{:error, reply}, {:stop, :shutdown, socket}} + + other -> + raise """ + channel #{inspect(socket.channel)}.join/3 is expected to return one of: + + {:ok, Socket.t} | + {:ok, reply :: map, Socket.t} | + {:error, reply :: map} + + got #{inspect(other)} + """ + end end - defp init_info(socket, channel, topic, reply, from) do + defp init_join(socket, channel, topic) do %{transport_pid: transport_pid, serializer: serializer, pubsub_server: pubsub_server} = socket Process.monitor(transport_pid) fastlane = {transport_pid, serializer, channel.__intercepts__()} PubSub.subscribe(pubsub_server, topic, link: true, fastlane: fastlane) - log_join(socket, topic, fn -> "Replied #{topic} :ok" end) - GenServer.reply(from, {:ok, reply}) {:noreply, %{socket | joined: true}} end - defp log_join(%{private: %{log_join: false}}, _topic, _func), do: :noop - defp log_join(%{private: %{log_join: level}}, _topic, func), do: Logger.log(level, func) - ## Handle results defp handle_result({:stop, reason, socket}, _callback) do diff --git a/lib/phoenix/endpoint.ex b/lib/phoenix/endpoint.ex index 0224ca5ba6..92d0d17523 100644 --- a/lib/phoenix/endpoint.ex +++ b/lib/phoenix/endpoint.ex @@ -237,131 +237,45 @@ defmodule Phoenix.Endpoint do ## Instrumentation - Phoenix supports instrumentation through an extensible API. Each endpoint - defines an `c:instrument/3` macro that both users and Phoenix internals can call - to instrument generic events. This macro is responsible for measuring the time - it takes for the event to be processed and for notifying a list of interested - instrumenter modules of this measurement. - - You can configure this list of instrumenter modules in the compile-time - configuration of your endpoint. (see the `:instrumenters` option above). The - way these modules express their interest in events is by exporting public - functions where the name of each function is the name of an event. For - example, if someone instruments the `:render_view` event, then each - instrumenter module interested in that event will have to export - `render_view/3`. - - ### Callbacks cycle - - The event callback sequence is: - - 1. The event callback is called *before* the event happens (in this case, - before the view is rendered) with the atom `:start` as the first - argument; see the "Before clause" section below - 2. The event occurs (in this case, the view is rendered) - 3. The same event callback is called again, this time with the atom `:stop` - as the first argument; see the "After clause" section below - - The second and third argument that each event callback takes depends on the - callback being an "after" or a "before" callback i.e. it depends on the - value of the first argument, `:start` or `:stop`. For this reason, most of - the time you will want to define (at least) two separate clauses for each - event callback, one for the "before" and one for the "after" callbacks. - - All event callbacks are run in the same process that calls the `c:instrument/3` - macro; hence, instrumenters should be careful to avoid performing blocking actions. - If an event callback fails in any way (exits, throws, or raises), it won't - affect anything as the error is caught, but the failure will be logged. Note - that "after" callbacks are not guaranteed to be called as, for example, a link - may break before they've been called. - - #### "Before" clause - - When the first argument to an event callback is `:start`, the signature of - that callback is: - - event_callback(:start, compile_metadata, runtime_metadata) - - where: - - * `compile_metadata` is a map of compile-time metadata about the environment - where `instrument/3` has been called. It contains the module where the - instrumentation is happening (under the `:module` key), the file and line - (`:file` and `:line`), and the function inside which the instrumentation - is happening (under `:function`). This information can be used arbitrarily - by the callback - * `runtime_metadata` is a map of runtime data that the instrumentation - passes to the callbacks. This can be used for any purposes: for example, - when instrumenting the rendering of a view, the name of the view could be - passed in these runtime data so that instrumenters know which view is - being rendered (`instrument(:view_render, %{view: "index.html"}, fn - ...)`) - - #### "After" clause - - When the first argument to an event callback is `:stop`, the signature of that - callback is: - - event_callback(:stop, time_diff, result_of_before_callback) - - where: - - * `time_diff` is an integer representing the time it took to execute the - instrumented function **in native units** - - * `result_of_before_callback` is the return value of the "before" clause of - the same `event_callback`. This is a means of passing data from the - "before" clause to the "after" clause when instrumenting - - The return value of each "before" event callback will be stored and passed to - the corresponding "after" callback. - - ### Using instrumentation - - Each Phoenix endpoint defines its own `instrument/3` macro. This macro is - called like this: - - require MyApp.Endpoint - MyApp.Endpoint.instrument(:render_view, %{view: "index.html"}, fn -> - # actual view rendering - end) - - All the instrumenter modules that export a `render_view/3` function will be - notified of the event so that they can perform their respective actions. - - ### Phoenix default events - - By default, Phoenix instruments the following events: - - * `:phoenix_controller_call` - the entire controller pipeline. - The `%Plug.Conn{}` is passed as runtime metadata - * `:phoenix_controller_render` - the rendering of a view from a - controller. The map of runtime metadata passed to instrumentation - callbacks has the `:view` key - for the name of the view, e.g. `HexWeb.ErrorView`, - the `:template` key - for the name of the template, e.g., - `"index.html"`, the `:format` key - for the format of the template, and - the `:conn` key - containing the `%Plug.Conn{}` - * `:phoenix_error_render` - the rendering of an error view when an exception, - throw, or exit is caught. The map of runtime metadata contains the `:status` - key of the error's HTTP status code, the `:conn` key containg the - `%Plug.Conn{}`, as well as the `:kind`, `:reason`, and `:stacktrace` of - the caught error - * `:phoenix_channel_join` - the joining of a channel. The `%Phoenix.Socket{}` - and join params are passed as runtime metadata via `:socket` and `:params` - * `:phoenix_channel_receive` - the receipt of an incoming message over a - channel. The `%Phoenix.Socket{}`, payload, event, and ref are passed as - runtime metadata via `:socket`, `:params`, `:event`, and `:ref` - * `:phoenix_socket_connect` - the connection of the user socket transport. - The map of runtime metadata contains the `:transport`, `:params`, a map of - `connect_info`, and the `:user_socket` module. - - ### Dynamic instrumentation - - If you want to instrument a piece of code, but the endpoint that should - instrument it (the one that contains the `c:instrument/3` macro you want to use) - is not known at compile time, only at runtime, you can use the - `Phoenix.Endpoint.instrument/4` macro. Refer to its documentation for more - information. + Phoenix uses the `:telemetry` library for instrumentation. The following events + are published by Phoenix with the following measurements and metadata: + + * `[:phoenix, :endpoint, :start]` - dispatched by `Plug.Telemetry` in your + endpoint at the beginning of every request. + * Measurement: `%{time: System.monotonic_time}` + * Metadata: `%{conn: Plug.Conn.t}` + + * `[:phoenix, :endpoint, :stop]` - dispatched by `Plug.Telemetry` in your + endpoint whenever the response is sent + * Measurement: `%{duration: native_time}` + * Metadata: `%{conn: Plug.Conn.t}` + + * `[:phoenix, :router_dispatch, :start]` - dispatched by `Phoenix.Router` + before dispatching to a matched route + * Measurement: `%{time: System.monotonic_time}` + * Metadata: `%{conn: Plug.Conn.t, route: binary, plug: module, plug_opts: term, path_params: map, pipe_through: [atom]}` + + * `[:phoenix, :router_dispatch, :stop]` - dispatched by `Phoenix.Router` + after successfully dispatching to a matched route + * Measurement: `%{duration: native_time}` + * Metadata: `%{conn: Plug.Conn.t, route: binary, plug: module, plug_opts: term, path_params: map, pipe_through: [atom]}` + + * `[:phoenix, :error_rendered]` - dispatched at the end of an error view being rendered + * Measurement: `%{duration: native_time}` + * Metadata: `%{status: Plug.Conn.status, kind: Exception.kind, reason: term, stacktrace: Exception.stacktrace}` + + * `[:phoenix, :socket_connected]` - dispatched at the end of a socket connection + * Measurement: `%{duration: native_time}` + * Metadata: `%{endpoint: atom, transport: atom, params: term, connect_info: map, vsn: binary, user_socket: atom, result: :ok | :error, serializer: atom}` + + * `[:phoenix, :channel_joined]` - dispatched at the end of a channel join + * Measurement: `%{duration: native_time}` + * Metadata: `%{params: term, socket: Phoenix.Socket.t}` + + * `[:phoenix, :channel_handled_in]` - dispatched at the end of a channel handle in + * Measurement: `%{duration: native_time}` + * Metadata: `%{event: binary, params: term, socket: Phoenix.Socket.t}` + """ @type topic :: String.t @@ -979,31 +893,7 @@ defmodule Phoenix.Endpoint do end end - @doc """ - Instruments the given function using the instrumentation provided by - the given endpoint. - - To specify the endpoint that will provide instrumentation, the first argument - can be: - - * a module name - the endpoint itself - * a `Plug.Conn` struct - this macro will look for the endpoint module in the - `:private` field of the connection; if it's not there, `fun` will be - executed with no instrumentation - * a `Phoenix.Socket` struct - this macro will look for the endpoint module in the - `:endpoint` field of the socket; if it's not there, `fun` will be - executed with no instrumentation - - Usually, users should prefer to instrument events using the `c:instrument/3` - macro defined in every Phoenix endpoint. This macro should only be used for - cases when the endpoint is dynamic and not known at compile time. - - ## Examples - - endpoint = MyApp.Endpoint - Phoenix.Endpoint.instrument endpoint, :render_view, fn -> ... end - - """ + @doc false defmacro instrument(endpoint_or_conn_or_socket, event, runtime \\ Macro.escape(%{}), fun) do compile = Phoenix.Endpoint.Instrument.strip_caller(__CALLER__) |> Macro.escape() diff --git a/lib/phoenix/endpoint/instrument.ex b/lib/phoenix/endpoint/instrument.ex index 5b289612a4..ba100f3ea0 100644 --- a/lib/phoenix/endpoint/instrument.ex +++ b/lib/phoenix/endpoint/instrument.ex @@ -95,7 +95,7 @@ defmodule Phoenix.Endpoint.Instrument do raise ":instrumenters must be a list of instrumenter modules" end - events_to_instrumenters([Phoenix.Logger | instrumenters]) + events_to_instrumenters(instrumenters) end # Strips a `Macro.Env` struct, leaving only interesting compile-time metadata. diff --git a/lib/phoenix/endpoint/render_errors.ex b/lib/phoenix/endpoint/render_errors.ex index f73a6d2f0f..dc17951a7f 100644 --- a/lib/phoenix/endpoint/render_errors.ex +++ b/lib/phoenix/endpoint/render_errors.ex @@ -66,17 +66,20 @@ defmodule Phoenix.Endpoint.RenderErrors do end defp instrument_render_and_send(conn, kind, reason, stack, opts) do - level = Keyword.get(opts, :log_level, :debug) + level = Keyword.get(opts, :log, :debug) status = status(kind, reason) conn = error_conn(conn, kind, reason) - metadata = %{status: status, conn: conn, kind: kind, reason: reason, stacktrace: stack, log_level: level} + start = System.monotonic_time() + metadata = %{status: status, kind: kind, reason: reason, stacktrace: stack, log: level} - conn = - Phoenix.Endpoint.instrument(conn, :phoenix_error_render, metadata, fn -> - render(conn, status, kind, reason, stack, opts) - end) - - send_resp(conn) + try do + conn + |> render(status, kind, reason, stack, opts) + |> send_resp() + after + duration = System.monotonic_time() - start + :telemetry.execute([:phoenix, :error_rendered], %{duration: duration}, metadata) + end end defp error_conn(_conn, :error, %NoRouteError{conn: conn}), do: conn diff --git a/lib/phoenix/logger.ex b/lib/phoenix/logger.ex index fd4d7c6c88..fc4f5a0008 100644 --- a/lib/phoenix/logger.ex +++ b/lib/phoenix/logger.ex @@ -25,67 +25,40 @@ defmodule Phoenix.Logger do except those that match exactly `id` or `order`. If a kept parameter matches, all parameters nested under that one will also be kept. """ - require Logger - import Phoenix.Controller - - def phoenix_error_render(:start, _compile, %{log_level: false}), do: :ok - def phoenix_error_render(:start, _, %{log_level: level} = runtime) do - %{status: status, kind: kind, reason: reason} = runtime - Logger.log(level, fn -> - ["Converted #{kind} #{error_banner(kind, reason)} to #{status} response"] - end) - :ok - end - def phoenix_error_render(:stop, _time_diff, :ok), do: :ok + require Logger - defp error_banner(:error, %type{}), do: inspect(type) - defp error_banner(_kind, reason), do: inspect(reason) + @doc false + def install do + handlers = %{ + [:phoenix, :endpoint, :start] => &phoenix_endpoint_start/4, + [:phoenix, :endpoint, :stop] => &phoenix_endpoint_stop/4, + [:phoenix, :router_dispatch, :start] => &phoenix_router_dispatch_start/4, + # [:phoenix, :router_dispatch, :stop] => &phoenix_router_dispatch_stop/4, + [:phoenix, :error_rendered] => &phoenix_error_rendered/4, + [:phoenix, :socket_connected] => &phoenix_socket_connected/4, + [:phoenix, :channel_joined] => &phoenix_channel_joined/4, + [:phoenix, :channel_handled_in] => &phoenix_channel_handled_in/4 + } - def phoenix_controller_call(:start, _compile, %{log_level: false}), do: :ok - def phoenix_controller_call(:start, %{module: module}, %{log_level: level, conn: conn}) do - Logger.log level, fn -> - controller = inspect(module) - action = conn |> action_name() |> Atom.to_string() - ["Processing with ", controller, ?., action, ?/, ?2, ?\n, - " Parameters: ", params(conn.params), ?\n, - " Pipelines: ", inspect(conn.private[:phoenix_pipelines])] + for {key, fun} <- handlers do + :telemetry.attach({__MODULE__, key}, key, fun, :ok) end - :ok end - def phoenix_controller_call(:stop, _time_diff, :ok), do: :ok - def phoenix_channel_join(:start, _compile, %{socket: socket, params: params}) do - log_join(socket.topic, socket, params) - end - def phoenix_channel_join(:stop, _compile, :ok), do: :ok - - def phoenix_channel_receive(:start, _compile, meta) do - %{socket: socket, params: params, event: event} = meta - log_receive(socket.topic, event, socket, params) - end - def phoenix_channel_receive(:stop, _compile, :ok), do: :ok - - def phoenix_socket_connect(:start, _compile, %{log: false}), do: :ok - def phoenix_socket_connect(:start, _compile, %{log: level} = meta) do - %{ - transport: transport, - params: params, - connect_info: connect_info, - user_socket: user_socket, - } = meta + @doc false + def duration(duration) do + duration = System.convert_time_unit(duration, :native, :microsecond) - Logger.log(level, fn -> - "CONNECT #{inspect(user_socket)}\n" <> - " Transport: #{inspect(transport)}\n" <> - " Connect Info: #{inspect(connect_info)}\n" <> - " Parameters: #{inspect(filter_values(params))}" - end) + if duration > 1000 do + [duration |> div(1000) |> Integer.to_string(), "ms"] + else + [Integer.to_string(duration), "µs"] + end end - def phoenix_socket_connect(:stop, _compile, _), do: :ok @doc false - def filter_values(values, params \\ Application.get_env(:phoenix, :filter_parameters)) + def filter_values(values, params \\ Application.get_env(:phoenix, :filter_parameters, [])) def filter_values(values, {:discard, params}), do: discard_values(values, params) def filter_values(values, {:keep, params}), do: keep_values(values, params) def filter_values(values, params), do: discard_values(values, params) @@ -93,66 +66,196 @@ defmodule Phoenix.Logger do defp discard_values(%{__struct__: mod} = struct, _params) when is_atom(mod) do struct end + defp discard_values(%{} = map, params) do - Enum.into map, %{}, fn {k, v} -> + Enum.into(map, %{}, fn {k, v} -> if is_binary(k) and String.contains?(k, params) do {k, "[FILTERED]"} else {k, discard_values(v, params)} end - end + end) end - defp discard_values([_|_] = list, params) do + + defp discard_values([_ | _] = list, params) do Enum.map(list, &discard_values(&1, params)) end + defp discard_values(other, _params), do: other defp keep_values(%{__struct__: mod}, _params) when is_atom(mod), do: "[FILTERED]" + defp keep_values(%{} = map, params) do - Enum.into map, %{}, fn {k, v} -> + Enum.into(map, %{}, fn {k, v} -> if is_binary(k) and k in params do {k, discard_values(v, [])} else {k, keep_values(v, params)} end - end + end) end - defp keep_values([_|_] = list, params) do + + defp keep_values([_ | _] = list, params) do Enum.map(list, &keep_values(&1, params)) end + defp keep_values(_other, _params), do: "[FILTERED]" - defp params(%Plug.Conn.Unfetched{}), do: "[UNFETCHED]" - defp params(params) do - params - |> filter_values() - |> inspect() + ## Event: [:phoenix, :endpoint, *] + + defp phoenix_endpoint_start(_, _, %{conn: conn} = metadata, _) do + level = metadata[:options][:log] || :info + + Logger.log(level, fn -> + %{method: method, request_path: request_path} = conn + [method, ?\s, request_path] + end) end - defp log_receive("phoenix" <> _, _event, _socket, _params), do: :ok - defp log_receive(topic, event, socket, params) do - channel_log(:log_handle_in, socket, fn -> - "INCOMING #{inspect event} on #{inspect topic} to #{inspect(socket.channel)}\n" <> - " Parameters: #{inspect filter_values(params)}" + defp phoenix_endpoint_stop(_, %{duration: duration}, %{conn: conn} = metadata, _) do + level = metadata[:options][:log] || :info + + Logger.log(level, fn -> + %{status: status, state: state} = conn + status = Integer.to_string(status) + [connection_type(state), ?\s, status, " in ", duration(duration)] + end) + end + + defp connection_type(:set_chunked), do: "Chunked" + defp connection_type(_), do: "Sent" + + ## Event: [:phoenix, :error_rendered] + + defp phoenix_error_rendered(_, _, %{log: false}, _), do: :ok + + defp phoenix_error_rendered(_, _, %{log: level, status: status, kind: kind, reason: reason}, _) do + Logger.log(level, fn -> + [ + "Converted ", + Atom.to_string(kind), + ?\s, + error_banner(kind, reason), + " to ", + Integer.to_string(status), + " response" + ] end) end - defp log_join("phoenix" <> _, _socket, _params), do: :ok - defp log_join(topic, socket, params) do + defp error_banner(:error, %type{}), do: inspect(type) + defp error_banner(_kind, reason), do: inspect(reason) + + ## Event: [:phoenix, :routed, *] + + defp phoenix_router_dispatch_start(_, _, %{log: false}, _), do: :ok + + defp phoenix_router_dispatch_start(_, _, metadata, _) do + %{log: level, conn: conn, pipe_through: pipe_through, plug: plug, plug_opts: plug_opts} = + metadata + + Logger.log(level, fn -> + [ + "Processing with ", + inspect(plug), + maybe_action(plug_opts), + ?\n, + " Parameters: ", + params(conn.params), + ?\n, + " Pipelines: ", + inspect(pipe_through) + ] + end) + end + + defp maybe_action(action) when is_atom(action), do: [?., Atom.to_string(action), ?/, ?2] + defp maybe_action(_), do: [] + + defp params(%Plug.Conn.Unfetched{}), do: "[UNFETCHED]" + defp params(params), do: params |> filter_values() |> inspect() + + ## Event: [:phoenix, :socket_connected] + + defp phoenix_socket_connected(_, _, %{log: false}, _), do: :ok + + defp phoenix_socket_connected(_, %{duration: duration}, %{log: level} = meta, _) do + Logger.log(level, fn -> + %{ + transport: transport, + params: params, + connect_info: connect_info, + user_socket: user_socket, + result: result, + serializer: serializer + } = meta + + [ + connect_result(result), + inspect(user_socket), + " in ", + duration(duration), + "\n Transport: ", + inspect(transport), + "\n Serializer: ", + inspect(serializer), + "\n Connect Info: ", + inspect(connect_info), + "\n Parameters: ", + inspect(filter_values(params)) + ] + end) + end + + defp connect_result(:ok), do: "CONNECTED TO " + defp connect_result(:error), do: "REFUSED CONNECTION TO " + + ## Event: [:phoenix, :channel_joined] + + def phoenix_channel_joined(_, %{duration: duration}, %{socket: socket} = metadata, _) do channel_log(:log_join, socket, fn -> - "JOIN #{inspect topic} to #{inspect(socket.channel)}\n" <> - " Transport: #{inspect socket.transport}\n" <> - " Serializer: #{inspect socket.serializer}\n" <> - " Parameters: #{inspect filter_values(params)}" + %{result: result, params: params} = metadata + + [ + join_result(result), + socket.topic, + " in ", + duration(duration), + "\n Parameters: ", + inspect(filter_values(params)) + ] end) end - defp channel_log(log_option, %Phoenix.Socket{private: private}, message_or_func) do - case Map.fetch(private, log_option) do - {:ok, false} -> :ok - {:ok, level} -> Logger.log(level, message_or_func) - end + defp join_result(:ok), do: "JOINED " + defp join_result(:error), do: "REFUSED JOIN " + + ## Event: [:phoenix, :channel_handle_in] - :ok + def phoenix_channel_handled_in(_, %{duration: duration}, %{socket: socket} = metadata, _) do + channel_log(:log_handle_in, socket, fn -> + %{event: event, params: params} = metadata + + [ + "HANDLED ", + event, + " INCOMING ON ", + socket.topic, + " (", + inspect(socket.channel), + ") in ", + duration(duration), + "\n Parameters: ", + inspect(filter_values(params)) + ] + end) + end + + defp channel_log(_log_option, %{topic: "phoenix" <> _}, _fun), do: :ok + + defp channel_log(log_option, %{private: private}, fun) do + if level = Map.get(private, log_option) do + Logger.log(level, fun) + end end end diff --git a/lib/phoenix/router.ex b/lib/phoenix/router.ex index 110cd18a85..3408c24454 100644 --- a/lib/phoenix/router.ex +++ b/lib/phoenix/router.ex @@ -266,13 +266,24 @@ defmodule Phoenix.Router do def __call__(%{private: %{phoenix_bypass: :all}} = conn, _match) do conn end - def __call__(conn, {path_params, prepare, pipeline, {plug, opts}}) do - case conn |> prepare.(path_params) |> pipeline.() do + def __call__(conn, {metadata, prepare, pipeline, {plug, opts}}) do + conn = prepare.(conn, metadata) + start = System.monotonic_time() + metadata = %{metadata | conn: conn} + :telemetry.execute([:phoenix, :router_dispatch, :start], %{time: start}, metadata) + + case pipeline.(conn) do %Plug.Conn{halted: true} = halted_conn -> halted_conn %Plug.Conn{} = piped_conn -> try do plug.call(piped_conn, plug.init(opts)) + else + conn -> + duration = System.monotonic_time() - start + metadata = %{metadata | conn: conn} + :telemetry.execute([:phoenix, :router_dispatch, :stop], %{duration: duration}, metadata) + conn rescue e in Plug.Conn.WrapperError -> Plug.Conn.WrapperError.reraise(e) @@ -300,6 +311,7 @@ defmodule Phoenix.Router do """ def call(conn, _opts) do %{method: method, path_info: path_info, host: host} = conn = prepare(conn) + case __match_route__(method, Enum.map(path_info, &URI.decode/1), host) do :error -> raise NoRouteError, conn: conn, router: __MODULE__ match -> Phoenix.Router.__call__(conn, match) @@ -389,8 +401,8 @@ defmodule Phoenix.Router do @doc false def __match_route__(unquote(verb_match), unquote(path), unquote(host)) do - {unquote(path_params), - fn var!(conn, :conn), var!(path_params, :conn) -> unquote(prepare) end, + {unquote(build_metadata(route, path_params)), + fn var!(conn, :conn), %{path_params: var!(path_params, :conn)} -> unquote(prepare) end, &unquote(Macro.var(pipe_name, __MODULE__))/1, unquote(dispatch)} end @@ -399,11 +411,25 @@ defmodule Phoenix.Router do {quoted, known_pipelines} end + defp build_metadata(route, path_params) do + %{path: path, plug: plug, plug_opts: plug_opts, log: log, pipe_through: pipe_through} = route + + pairs = [ + conn: nil, + route: path, + plug: plug, + plug_opts: Macro.escape(plug_opts), + log: log, + path_params: path_params, + pipe_through: pipe_through + ] + + {:%{}, [], pairs} + end + defp build_pipes(name, []) do quote do - defp unquote(name)(conn) do - Plug.Conn.put_private(conn, :phoenix_pipelines, []) - end + defp unquote(name)(conn), do: conn end end @@ -412,22 +438,27 @@ defmodule Phoenix.Router do {conn, body} = Plug.Builder.compile(__ENV__, plugs, init_mode: Phoenix.plug_init_mode()) quote do - defp unquote(name)(unquote(conn)) do - unquote(conn) = Plug.Conn.put_private(unquote(conn), :phoenix_pipelines, unquote(pipe_through)) - unquote(body) - end + defp unquote(name)(unquote(conn)), do: unquote(body) end end @doc """ Generates a route match based on an arbitrary HTTP method. - Useful for defining routes not included in the builtin macros: - - #{Enum.map_join(@http_methods, ", ", &"`#{&1}`")} + Useful for defining routes not included in the builtin macros. The catch-all verb, `:*`, may also be used to match all HTTP methods. + ## Options + + * `:as` - configures the named helper exclusively + * `:log` - the level to log the route dispatching under, + may be set to false. Defaults to `:debug` + * `:host` - a string containing the host scope, or prefix host scope, + ie `"foo.bar.com"`, `"foo."` + * `:private` - a map of private data to merge into the connection when a route matches + * `:assigns` - a map of data to merge into the connection when a route matches + ## Examples match(:move, "/events/:id", EventController, :move) @@ -442,6 +473,10 @@ defmodule Phoenix.Router do for verb <- @http_methods do @doc """ Generates a route to handle a #{verb} request to the given path. + + #{verb}("/events/:id", EventController, :action) + + See `match/5` for options. """ defmacro unquote(verb)(path, plug, plug_opts, options \\ []) do add_route(:match, unquote(verb), path, plug, plug_opts, options) @@ -692,6 +727,8 @@ defmodule Phoenix.Router do ie `"foo.bar.com"`, `"foo."` * `:private` - a map of private data to merge into the connection when a route matches * `:assigns` - a map of data to merge into the connection when a route matches + * `:log` - the level to log the route dispatching under, + may be set to false. Defaults to `:debug` """ defmacro scope(options, do: context) do diff --git a/lib/phoenix/router/route.ex b/lib/phoenix/router/route.ex index b5d0761222..4b284b9abf 100644 --- a/lib/phoenix/router/route.ex +++ b/lib/phoenix/router/route.ex @@ -20,11 +20,12 @@ defmodule Phoenix.Router.Route do * `:private` - the private route info * `:assigns` - the route info * `:pipe_through` - the pipeline names as a list of atoms + * `:log` - if we should log the matching of this route """ defstruct [:verb, :line, :kind, :path, :host, :plug, :plug_opts, - :helper, :private, :pipe_through, :assigns] + :helper, :private, :pipe_through, :assigns, :log] @type t :: %Route{} @@ -44,16 +45,16 @@ defmodule Phoenix.Router.Route do Receives the verb, path, plug, options and helper and returns a `Phoenix.Router.Route` struct. """ - @spec build(non_neg_integer, :match | :forward, String.t, String.t, String.t | nil, atom, atom, atom | nil, atom, %{}, %{}) :: t - def build(line, kind, verb, path, host, plug, plug_opts, helper, pipe_through, private, assigns) + @spec build(non_neg_integer, :match | :forward, String.t, String.t, String.t | nil, atom, atom, atom | nil, atom, %{}, %{}, atom) :: t + def build(line, kind, verb, path, host, plug, plug_opts, helper, pipe_through, private, assigns, log) when is_atom(verb) and (is_binary(host) or is_nil(host)) and is_atom(plug) and (is_binary(helper) or is_nil(helper)) and - is_list(pipe_through) and is_map(private) and is_map(assigns) - and kind in [:match, :forward] do + is_list(pipe_through) and is_map(private) and is_map(assigns) and + is_atom(log) and kind in [:match, :forward] do %Route{kind: kind, verb: verb, path: path, host: host, private: private, plug: plug, plug_opts: plug_opts, helper: helper, - pipe_through: pipe_through, assigns: assigns, line: line} + pipe_through: pipe_through, assigns: assigns, line: line, log: log} end @doc """ diff --git a/lib/phoenix/router/scope.ex b/lib/phoenix/router/scope.ex index 03c7049eae..8bf1553e78 100644 --- a/lib/phoenix/router/scope.ex +++ b/lib/phoenix/router/scope.ex @@ -6,7 +6,7 @@ defmodule Phoenix.Router.Scope do @pipes :phoenix_pipeline_scopes @top :phoenix_top_scopes - defstruct path: [], alias: [], as: [], pipes: [], host: nil, private: %{}, assigns: %{} + defstruct path: [], alias: [], as: [], pipes: [], host: nil, private: %{}, assigns: %{}, log: :debug @doc """ Initializes the scope. @@ -31,9 +31,11 @@ defmodule Phoenix.Router.Scope do raise ArgumentError, "`static` is a reserved route prefix generated from #{inspect plug} or `:as` option" end - {path, host, alias, as, pipes, private, assigns} = + {path, host, alias, as, pipes, private, assigns, log} = join(module, path, plug, alias?, as, private, assigns) - Phoenix.Router.Route.build(line, kind, verb, path, host, alias, plug_opts, as, pipes, private, assigns) + + log = Keyword.get(opts, :log, log) + Phoenix.Router.Route.build(line, kind, verb, path, host, alias, plug_opts, as, pipes, private, assigns, log) end @doc """ @@ -106,7 +108,8 @@ defmodule Phoenix.Router.Scope do host: host || top.host, pipes: top.pipes, private: Map.merge(top.private, private), - assigns: Map.merge(top.assigns, assigns) + assigns: Map.merge(top.assigns, assigns), + log: Keyword.get(opts, :log, top.log) }) end @@ -145,6 +148,7 @@ defmodule Phoenix.Router.Scope do defp join(module, path, alias, alias?, as, private, assigns) do top = get_top(module) + joined_alias = if alias? do join_alias(top, alias) @@ -153,7 +157,7 @@ defmodule Phoenix.Router.Scope do end {join_path(top, path), top.host, joined_alias, join_as(top, as), top.pipes, - Map.merge(top.private, private), Map.merge(top.assigns, assigns)} + Map.merge(top.private, private), Map.merge(top.assigns, assigns), top.log} end defp join_path(top, path) do diff --git a/lib/phoenix/socket.ex b/lib/phoenix/socket.ex index 64af6ebf83..de10daebc1 100644 --- a/lib/phoenix/socket.ex +++ b/lib/phoenix/socket.ex @@ -431,31 +431,37 @@ defmodule Phoenix.Socket do } = map vsn = params["vsn"] || "1.0.0" + options = Keyword.merge(socket_options, options) - log = Keyword.get(options, :log, :info) - meta = Map.merge(map, %{vsn: vsn, user_socket: user_socket, log: log}) + start = System.monotonic_time() + + case negotiate_serializer(Keyword.fetch!(options, :serializer), vsn) do + {:ok, serializer} -> + result = user_connect(user_socket, endpoint, transport, serializer, params, connect_info) + + metadata = %{ + endpoint: endpoint, + transport: transport, + params: params, + connect_info: connect_info, + vsn: vsn, + user_socket: user_socket, + log: Keyword.get(options, :log, :info), + result: result(result), + serializer: serializer + } - Phoenix.Endpoint.instrument(endpoint, :phoenix_socket_connect, meta, fn -> - case negotiate_serializer(Keyword.fetch!(options, :serializer), vsn) do - {:ok, serializer} -> - user_socket - |> user_connect(endpoint, transport, serializer, params, connect_info) - |> log_connect_result(user_socket, log) + duration = System.monotonic_time() - start + :telemetry.execute([:phoenix, :socket_connected], %{duration: duration}, metadata) + result - :error -> :error - end - end) + :error -> + :error + end end - defp log_connect_result(result, _user_socket, false = _level), do: result - defp log_connect_result({:ok, _} = result, user_socket, level) do - Logger.log(level, fn -> "Replied #{inspect(user_socket)} :ok" end) - result - end - defp log_connect_result(:error = result, user_socket, level) do - Logger.log(level, fn -> "Replied #{inspect(user_socket)} :error" end) - result - end + defp result({:ok, _}), do: :ok + defp result(:error), do: :error def __init__({state, %{id: id, endpoint: endpoint} = socket}) do _ = id && endpoint.subscribe(id, link: true) diff --git a/lib/phoenix/test/conn_test.ex b/lib/phoenix/test/conn_test.ex index d5e4caac3f..1ad99ea703 100644 --- a/lib/phoenix/test/conn_test.ex +++ b/lib/phoenix/test/conn_test.ex @@ -580,7 +580,7 @@ defmodule Phoenix.ConnTest do case router.__match_route__("GET", path_info, host || conn.host) do :error -> raise Phoenix.Router.NoRouteError, conn: conn, router: router - {path_params, _prepare, _pipes, _dispatch} -> + {%{path_params: path_params}, _prepare, _pipes, _dispatch} -> Enum.into(path_params, %{}, fn {key, val} -> {String.to_atom(key), val} end) end end diff --git a/mix.exs b/mix.exs index 912defdad6..1d62367ee9 100644 --- a/mix.exs +++ b/mix.exs @@ -56,7 +56,8 @@ defmodule Phoenix.MixProject do defp deps do [ - {:plug, "~> 1.7"}, + {:plug, "~> 1.8"}, + {:telemetry, "~> 0.4"}, {:phoenix_pubsub, "~> 1.1"}, # Optional deps @@ -65,7 +66,7 @@ defmodule Phoenix.MixProject do {:phoenix_html, "~> 2.13", optional: true}, # Docs dependencies - {:ex_doc, "~> 0.20.2", only: :docs}, + {:ex_doc, "~> 0.20", only: :docs}, {:inch_ex, "~> 0.2", only: :docs}, # Test dependencies @@ -153,6 +154,7 @@ defmodule Phoenix.MixProject do # Phoenix.Controller # Phoenix.Endpoint # Phoenix.Naming + # Phoenix.Logger # Phoenix.Param # Phoenix.Presence # Phoenix.Router @@ -168,8 +170,7 @@ defmodule Phoenix.MixProject do "Adapters and Plugs": [ Phoenix.CodeReloader, Phoenix.Endpoint.CowboyAdapter, - Phoenix.Endpoint.Cowboy2Adapter, - Phoenix.Logger, + Phoenix.Endpoint.Cowboy2Adapter ], "Socket and Transport": [ diff --git a/mix.lock b/mix.lock index dca5e30b5d..6aa34f3116 100644 --- a/mix.lock +++ b/mix.lock @@ -8,14 +8,15 @@ "jason": {:hex, :jason, "1.0.0", "0f7cfa9bdb23fed721ec05419bcee2b2c21a77e926bce0deda029b5adc716fe2", [:mix], [{:decimal, "~> 1.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm"}, "makeup": {:hex, :makeup, "0.8.0", "9cf32aea71c7fe0a4b2e9246c2c4978f9070257e5c9ce6d4a28ec450a839b55f", [:mix], [{:nimble_parsec, "~> 0.5.0", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm"}, "makeup_elixir": {:hex, :makeup_elixir, "0.13.0", "be7a477997dcac2e48a9d695ec730b2d22418292675c75aa2d34ba0909dcdeda", [:mix], [{:makeup, "~> 0.8", [hex: :makeup, repo: "hexpm", optional: false]}], "hexpm"}, - "mime": {:hex, :mime, "1.3.0", "5e8d45a39e95c650900d03f897fbf99ae04f60ab1daa4a34c7a20a5151b7a5fe", [:mix], [], "hexpm"}, + "mime": {:hex, :mime, "1.3.1", "30ce04ab3175b6ad0bdce0035cba77bba68b813d523d1aac73d9781b4d193cf8", [:mix], [], "hexpm"}, "nimble_parsec": {:hex, :nimble_parsec, "0.5.0", "90e2eca3d0266e5c53f8fbe0079694740b9c91b6747f2b7e3c5d21966bba8300", [:mix], [], "hexpm"}, "phoenix_html": {:hex, :phoenix_html, "2.13.0", "3bad10de5efb6c590f7aa5b316ad0d3faa054715414c9b562c410de4ffb885c5", [:mix], [{:plug, "~> 1.5", [hex: :plug, repo: "hexpm", optional: false]}], "hexpm"}, "phoenix_pubsub": {:hex, :phoenix_pubsub, "1.1.0", "d55e25ff1ff8ea2f9964638366dfd6e361c52dedfd50019353598d11d4441d14", [:mix], [], "hexpm"}, - "plug": {:hex, :plug, "1.7.1", "8516d565fb84a6a8b2ca722e74e2cd25ca0fc9d64f364ec9dbec09d33eb78ccd", [:mix], [{:mime, "~> 1.0", [hex: :mime, repo: "hexpm", optional: false]}, {:plug_crypto, "~> 1.0", [hex: :plug_crypto, repo: "hexpm", optional: false]}], "hexpm"}, + "plug": {:hex, :plug, "1.8.0", "9d2685cb007fe5e28ed9ac27af2815bc262b7817a00929ac10f56f169f43b977", [:mix], [{:mime, "~> 1.0", [hex: :mime, repo: "hexpm", optional: false]}, {:plug_crypto, "~> 1.0", [hex: :plug_crypto, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4", [hex: :telemetry, repo: "hexpm", optional: true]}], "hexpm"}, "plug_cowboy": {:hex, :plug_cowboy, "2.0.0", "ab0c92728f2ba43c544cce85f0f220d8d30fc0c90eaa1e6203683ab039655062", [:mix], [{:cowboy, "~> 2.5", [hex: :cowboy, repo: "hexpm", optional: false]}, {:plug, "~> 1.7", [hex: :plug, repo: "hexpm", optional: false]}], "hexpm"}, "plug_crypto": {:hex, :plug_crypto, "1.0.0", "18e49317d3fa343f24620ed22795ec29d4a5e602d52d1513ccea0b07d8ea7d4d", [:mix], [], "hexpm"}, "poison": {:hex, :poison, "3.1.0", "d9eb636610e096f86f25d9a46f35a9facac35609a7591b3be3326e99a0484665", [:mix], []}, "ranch": {:hex, :ranch, "1.6.2", "6db93c78f411ee033dbb18ba8234c5574883acb9a75af0fb90a9b82ea46afa00", [:rebar3], [], "hexpm"}, + "telemetry": {:hex, :telemetry, "0.4.0", "8339bee3fa8b91cb84d14c2935f8ecf399ccd87301ad6da6b71c09553834b2ab", [:rebar3], [], "hexpm"}, "websocket_client": {:git, "https://github.com/jeremyong/websocket_client.git", "9a6f65d05ebf2725d62fb19262b21f1805a59fbf", []}, } diff --git a/test/phoenix/endpoint/render_errors_test.exs b/test/phoenix/endpoint/render_errors_test.exs index 94415c60cb..61bf2a91d7 100644 --- a/test/phoenix/endpoint/render_errors_test.exs +++ b/test/phoenix/endpoint/render_errors_test.exs @@ -69,6 +69,11 @@ defmodule Phoenix.Endpoint.RenderErrorsTest do use Phoenix.Endpoint, otp_app: :phoenix end + setup do + Logger.disable(self()) + :ok + end + test "call/2 is overridden" do assert_raise RuntimeError, "oops", fn -> call(Router, :get, "/boom") @@ -122,6 +127,7 @@ defmodule Phoenix.Endpoint.RenderErrorsTest do end test "logs converted errors if response has not yet been sent" do + Logger.enable(self()) conn = put_endpoint(conn(:get, "/")) assert capture_log(fn -> @@ -246,11 +252,9 @@ defmodule Phoenix.Endpoint.RenderErrorsTest do assert body == "Layout: Got 500 from throw with GET" end - @tag :capture_log test "exception page is shown even with invalid format" do conn = conn(:get, "/") |> put_req_header("accept", "unknown/unknown") body = assert_render(500, conn, [], fn -> throw :hello end) - assert body == "Got 500 from throw with GET" end @@ -261,6 +265,8 @@ defmodule Phoenix.Endpoint.RenderErrorsTest do end test "captures warning when format is not supported" do + Logger.enable(self()) + assert capture_log(fn -> conn = conn(:get, "/") |> put_req_header("accept", "unknown/unknown") assert_render(500, conn, [], fn -> throw :hello end) @@ -268,6 +274,8 @@ defmodule Phoenix.Endpoint.RenderErrorsTest do end test "captures warning when format does not match error view" do + Logger.enable(self()) + assert capture_log(fn -> conn = conn(:get, "/?_format=unknown") assert_render(500, conn, [], fn -> throw :hello end) diff --git a/test/phoenix/integration/websocket_channels_test.exs b/test/phoenix/integration/websocket_channels_test.exs index 3ee13d6c92..892f5fcec1 100644 --- a/test/phoenix/integration/websocket_channels_test.exs +++ b/test/phoenix/integration/websocket_channels_test.exs @@ -305,24 +305,26 @@ defmodule Phoenix.Integration.WebSocketChannelsTest do log = capture_log(fn -> {:ok, _} = WebsocketClient.start_link(self(), "#{@vsn_path}&logging=enabled", @serializer) end) - assert log =~ "CONNECT #{inspect(UserSocket)}" + + assert log =~ "CONNECTED TO Phoenix.Integration.WebSocketChannelsTest.UserSocket in " + assert log =~ " Transport: :websocket" + assert log =~ " Connect Info: %{}" + assert log =~ " Serializer: #{inspect @serializer}" + assert log =~ " Parameters: %{\"logging\" => \"enabled\", \"vsn\" => #{inspect(@vsn)}}" end test "does not log user socket connect when disabled" do log = capture_log(fn -> - {:ok, _} = - WebsocketClient.start_link( - self(), - "ws://127.0.0.1:#{@port}/ws/connect_info/websocket?vsn=#{@vsn}", - @serializer - ) + {:ok, _} = WebsocketClient.start_link(self(), @vsn_path, @serializer) end) + assert log == "" end test "logs and filter params on join and handle_in" do topic = "room:admin-lobby2" {:ok, sock} = WebsocketClient.start_link(self(), "#{@vsn_path}&logging=enabled", @serializer) + log = capture_log fn -> WebsocketClient.join(sock, topic, %{"join" => "yes", "password" => "no"}) assert_receive %Message{event: "phx_reply", @@ -330,12 +332,16 @@ defmodule Phoenix.Integration.WebSocketChannelsTest do payload: %{"response" => %{}, "status" => "ok"}, ref: "1", topic: "room:admin-lobby2"} end + + assert log =~ "JOINED room:admin-lobby2 in " assert log =~ "Parameters: %{\"join\" => \"yes\", \"password\" => \"[FILTERED]\"}" log = capture_log fn -> WebsocketClient.send_event(sock, topic, "new_msg", %{"in" => "yes", "password" => "no"}) assert_receive %Message{event: "phx_reply", ref: "2"} end + + assert log =~ "HANDLED new_msg INCOMING ON room:admin-lobby2 (Phoenix.Integration.WebSocketChannelsTest.RoomChannel)" assert log =~ "Parameters: %{\"in\" => \"yes\", \"password\" => \"[FILTERED]\"}" end diff --git a/test/phoenix/logger_test.exs b/test/phoenix/logger_test.exs index 764c9f32d7..4c43f7079d 100644 --- a/test/phoenix/logger_test.exs +++ b/test/phoenix/logger_test.exs @@ -1,76 +1,5 @@ defmodule Phoenix.LoggerTest do use ExUnit.Case, async: true - use RouterHelper - import ExUnit.CaptureLog - - Application.put_env(:phoenix, __MODULE__.Endpoint, [ - server: false, - secret_key_base: String.duplicate("abcdefgh", 8), - ]) - - defmodule Endpoint do - use Phoenix.Endpoint, otp_app: :phoenix - end - - setup_all do - Endpoint.start_link() - :ok - end - - defmodule LoggerController do - use Phoenix.Controller - def index(conn, _params), do: text(conn, "index") - end - - defmodule NoLoggerController do - use Phoenix.Controller, log: false - def index(conn, _params), do: text(conn, "index") - end - - test "logs controller, action, format and parameters" do - output = capture_log fn -> - conn(:get, "/", foo: "bar", format: "html") - |> fetch_query_params - |> Endpoint.call([]) - |> put_private(:phoenix_pipelines, [:browser]) - |> action - end - assert output =~ "[debug] Processing with Phoenix.LoggerTest.LoggerController.index/2" - assert output =~ "Parameters: %{\"foo\" => \"bar\", \"format\" => \"html\"}" - assert output =~ "Pipelines: [:browser]" - end - - test "does not log when disabled" do - output = capture_log fn -> - conn(:get, "/", foo: "bar", format: "html") - |> fetch_query_params - |> put_private(:phoenix_pipelines, [:browser]) - |> Endpoint.call([]) - |> NoLoggerController.call(NoLoggerController.init(:index)) - end - assert output == "" - end - - test "filter parameter" do - output = capture_log fn -> - conn(:get, "/", foo: "bar", password: "should_not_show") - |> fetch_query_params - |> Endpoint.call([]) - |> action - end - - assert output =~ "Parameters: %{\"foo\" => \"bar\", \"password\" => \"[FILTERED]\"}" - end - - test "does not filter unfetched parameters" do - output = capture_log fn -> - conn(:get, "/", "{foo:bar}") - |> put_req_header("content-type", "application/json") - |> Endpoint.call([]) - |> action - end - assert output =~ "Parameters: [UNFETCHED]" - end describe "filter_values/2 with discard strategy" do test "in top level map" do @@ -134,55 +63,4 @@ defmodule Phoenix.LoggerTest do "ids" => ["[FILTERED]", "[FILTERED]"]} end end - - test "logs phoenix_channel_join as configured by the channel" do - log = capture_log(fn -> - socket = %Phoenix.Socket{private: %{log_join: :info}} - Phoenix.Logger.phoenix_channel_join(:start, %{}, %{socket: socket, params: %{}}) - end) - assert log =~ "JOIN" - - log = capture_log(fn -> - socket = %Phoenix.Socket{private: %{log_join: false}} - Phoenix.Logger.phoenix_channel_join(:start, %{}, %{socket: socket, params: %{}}) - end) - assert log == "" - end - - test "logs phoenix_channel_receive as configured by the channel" do - log = capture_log(fn -> - socket = %Phoenix.Socket{private: %{log_handle_in: :debug}} - Phoenix.Logger.phoenix_channel_receive(:start, %{}, %{socket: socket, event: "e", params: %{}}) - end) - assert log =~ "INCOMING" - - log = capture_log(fn -> - socket = %Phoenix.Socket{private: %{log_handle_in: false}} - Phoenix.Logger.phoenix_channel_receive(:start, %{}, %{socket: socket, event: "e", params: %{}}) - end) - assert log == "" - end - - test "logs phoenix_socket_connect as configured by the user socket" do - meta = %{ - transport: :websocket, - params: %{}, - connect_info: %{}, - user_socket: TestUserSocket, - } - - log = capture_log(fn -> - Phoenix.Logger.phoenix_socket_connect(:start, %{}, Map.put(meta, :log, :info)) - end) - assert log =~ "CONNECT TestUserSocket" - - log = capture_log(fn -> - Phoenix.Logger.phoenix_socket_connect(:start, %{}, Map.put(meta, :log, false)) - end) - assert log == "" - end - - defp action(conn) do - LoggerController.call(conn, LoggerController.init(:index)) - end end diff --git a/test/phoenix/router/pipeline_test.exs b/test/phoenix/router/pipeline_test.exs index 4268857abb..053838686e 100644 --- a/test/phoenix/router/pipeline_test.exs +++ b/test/phoenix/router/pipeline_test.exs @@ -74,11 +74,11 @@ defmodule Phoenix.Router.PipelineTest.Router do end defp put_assign(conn, value) do - assign conn, :stack, value + assign(conn, :stack, [value | conn.assigns[:stack] || []]) end defp put_params(conn, _) do - assign conn, :params, conn.params + assign(conn, :params, conn.params) end end @@ -95,26 +95,22 @@ defmodule Phoenix.Router.PipelineTest do test "does not invoke pipelines at root" do conn = call(Router, :get, "/root") - assert conn.private[:phoenix_pipelines] == [] assert conn.assigns[:stack] == nil end test "invokes pipelines per scope" do conn = call(Router, :get, "/browser/root") - assert conn.private[:phoenix_pipelines] == [:browser] - assert conn.assigns[:stack] == "browser" + assert conn.assigns[:stack] == ["browser"] end test "invokes pipelines in a nested scope" do conn = call(Router, :get, "/browser/api/root") - assert conn.private[:phoenix_pipelines] == [:browser, :api] - assert conn.assigns[:stack] == "api" + assert conn.assigns[:stack] == ["api", "browser"] end test "invokes multiple pipelines" do conn = call(Router, :get, "/browser-api/root") - assert conn.private[:phoenix_pipelines] == [:browser, :api] - assert conn.assigns[:stack] == "api" + assert conn.assigns[:stack] == ["api", "browser"] end test "halts on pipeline multiple pipelines" do diff --git a/test/phoenix/router/route_test.exs b/test/phoenix/router/route_test.exs index 08e03d82a2..77f8150121 100644 --- a/test/phoenix/router/route_test.exs +++ b/test/phoenix/router/route_test.exs @@ -11,44 +11,44 @@ defmodule Phoenix.Router.RouteTest do end test "builds a route based on verb, path, plug, plug options and helper" do - route = build(1, :match, :get, "/foo/:bar", nil, Hello, :world, "hello_world", [:foo, :bar], %{foo: "bar"}, %{bar: "baz"}) + route = build(1, :match, :get, "/foo/:bar", nil, Hello, :world, "hello_world", [:foo, :bar], %{foo: "bar"}, %{bar: "baz"}, :debug) assert route.kind == :match assert route.verb == :get assert route.path == "/foo/:bar" assert route.host == nil assert route.line == 1 - assert route.plug == Hello assert route.plug_opts == :world assert route.helper == "hello_world" assert route.pipe_through == [:foo, :bar] assert route.private == %{foo: "bar"} assert route.assigns == %{bar: "baz"} + assert route.log == :debug end test "builds expressions based on the route" do - exprs = build(1, :match, :get, "/foo/:bar", nil, Hello, :world, "hello_world", [], %{}, %{}) |> exprs + exprs = build(1, :match, :get, "/foo/:bar", nil, Hello, :world, "hello_world", [], %{}, %{}, :debug) |> exprs assert exprs.verb_match == "GET" assert exprs.path == ["foo", {:bar, [], nil}] assert exprs.binding == [{"bar", {:bar, [], nil}}] assert Macro.to_string(exprs.host) == "_" - exprs = build(1, :match, :get, "/", "foo.", Hello, :world, "hello_world", [:foo, :bar], %{foo: "bar"}, %{bar: "baz"}) |> exprs + exprs = build(1, :match, :get, "/", "foo.", Hello, :world, "hello_world", [:foo, :bar], %{foo: "bar"}, %{bar: "baz"}, :debug) |> exprs assert Macro.to_string(exprs.host) == "\"foo.\" <> _" - exprs = build(1, :match, :get, "/", "foo.com", Hello, :world, "hello_world", [], %{foo: "bar"}, %{bar: "baz"}) |> exprs + exprs = build(1, :match, :get, "/", "foo.com", Hello, :world, "hello_world", [], %{foo: "bar"}, %{bar: "baz"}, :debug) |> exprs assert Macro.to_string(exprs.host) == "\"foo.com\"" end test "builds a catch-all verb_match for match routes" do - route = build(1, :match, :*, "/foo/:bar", nil, __MODULE__, :world, "hello_world", [:foo, :bar], %{foo: "bar"}, %{bar: "baz"}) + route = build(1, :match, :*, "/foo/:bar", nil, __MODULE__, :world, "hello_world", [:foo, :bar], %{foo: "bar"}, %{bar: "baz"}, :debug) assert route.verb == :* assert route.kind == :match assert exprs(route).verb_match == {:_verb, [], nil} end test "builds a catch-all verb_match for forwarded routes" do - route = build(1, :forward, :*, "/foo/:bar", nil, __MODULE__, :world, "hello_world", [:foo, :bar], %{foo: "bar"}, %{bar: "baz"}) + route = build(1, :forward, :*, "/foo/:bar", nil, __MODULE__, :world, "hello_world", [:foo, :bar], %{foo: "bar"}, %{bar: "baz"}, :debug) assert route.verb == :* assert route.kind == :forward assert exprs(route).verb_match == {:_verb, [], nil} @@ -68,10 +68,10 @@ defmodule Phoenix.Router.RouteTest do opts = %{a: ~r/foo/} escaped_opts = Macro.escape(opts) - route = build(1, :match, :*, "/foo", nil, __MODULE__, opts, "hello_world", [], %{}, %{}) + route = build(1, :match, :*, "/foo", nil, __MODULE__, opts, "hello_world", [], %{}, %{}, :debug) assert {__MODULE__, escaped_opts} == exprs(route).dispatch - fwd_route = build(1, :forward, :*, "/foo", nil, __MODULE__, opts, "hello_world", [], %{}, %{}) + fwd_route = build(1, :forward, :*, "/foo", nil, __MODULE__, opts, "hello_world", [], %{}, %{}, :debug) assert {_, {:{}, _, [_, __MODULE__, ^escaped_opts]}} = exprs(fwd_route).dispatch end end diff --git a/test/phoenix/router/routing_test.exs b/test/phoenix/router/routing_test.exs index e55aa5ad8a..2bc08aa9a0 100644 --- a/test/phoenix/router/routing_test.exs +++ b/test/phoenix/router/routing_test.exs @@ -2,6 +2,13 @@ defmodule Phoenix.Router.RoutingTest do use ExUnit.Case, async: true use RouterHelper + import ExUnit.CaptureLog + + defmodule SomePlug do + def init(opts), do: opts + def call(conn, _opts), do: conn + end + defmodule UserController do use Phoenix.Controller def index(conn, _params), do: text(conn, "users index") @@ -35,8 +42,16 @@ defmodule Phoenix.Router.RoutingTest do match :move, "/move", UserController, :move match :*, "/any", UserController, :any + scope log: :info do + pipe_through :noop + get "/plug", SomePlug, [] + end + + get "/no_log", SomePlug, [], log: false get "/users/:user_id/files/:id", UserController, :image get "/*path", UserController, :not_found + + defp noop(conn, _), do: conn end setup do @@ -165,4 +180,40 @@ defmodule Phoenix.Router.RoutingTest do assert conn.status == 200 assert conn.resp_body == "users any" end + + describe "logging" do + setup do + Logger.enable(self()) + :ok + end + + test "logs controller and action with (path) parameters" do + assert capture_log(fn -> call(Router, :get, "/users/1", foo: "bar") end) =~ """ + [debug] Processing with Phoenix.Router.RoutingTest.UserController.show/2 + Parameters: %{"foo" => "bar", "id" => "1"} + Pipelines: [] + """ + end + + test "logs controller and action with filtered parameters" do + assert capture_log(fn -> call(Router, :get, "/users/1", password: "bar") end) =~ """ + [debug] Processing with Phoenix.Router.RoutingTest.UserController.show/2 + Parameters: %{"id" => "1", "password" => "[FILTERED]"} + Pipelines: [] + """ + end + + test "logs plug with pipeline and custom level" do + assert capture_log(fn -> call(Router, :get, "/plug") end) =~ """ + [info] Processing with Phoenix.Router.RoutingTest.SomePlug + Parameters: %{} + Pipelines: [:noop] + """ + end + + test "does not log when log is set to false" do + refute capture_log(fn -> call(Router, :get, "/no_log", foo: "bar") end) =~ + "Processing with Phoenix.Router.RoutingTest.SomePlug" + end + end end diff --git a/test/phoenix/test/conn_test.exs b/test/phoenix/test/conn_test.exs index 7c62f085df..1ab22cfa80 100644 --- a/test/phoenix/test/conn_test.exs +++ b/test/phoenix/test/conn_test.exs @@ -59,6 +59,7 @@ defmodule Phoenix.Test.ConnTest do @endpoint Endpoint setup_all do + Logger.disable(self()) Endpoint.start_link() :ok end diff --git a/test/phoenix/token_test.exs b/test/phoenix/token_test.exs index d54754a3b0..cb4199ae62 100644 --- a/test/phoenix/token_test.exs +++ b/test/phoenix/token_test.exs @@ -2,7 +2,10 @@ defmodule Phoenix.TokenTest do use ExUnit.Case, async: true alias Phoenix.Token - @moduletag :capture_log + setup do + Logger.disable(self()) + :ok + end defmodule TokenEndpoint do def config(:secret_key_base), do: "abc123"