Repository: phoenixframework/phoenix
Pull request #4196 (2021-02-03 06:18:31)

Dynamic Phoenix.Logger level
Related to #4194, this change would let us remove a wrapper that needs to know too much about Plug.Telemetry internals and replace it with this:

```ex
# lib/my_app_web/endpoint.ex

plug Plug.Telemetry,
  event_prefix: [:phoenix, :endpoint],
  log: &__MODULE__.log_level/1

@quiet_paths ["alive", "health", "ready", "favicon.ico"]
def log_level(%{path_info: [head | _]}) when head in @quiet_paths, do: false
def log_level(_), do: :info
```

Incidentally, deploying the wrapper reduced our production log output by a non-insignificant amount (screenshot below) :)

![image](https://user-images.githubusercontent.com/168677/106706342-68123e00-65a4-11eb-9c74-6ff4e9d9317a.png)

Wdyt?

josevalim: Looks good. My main concern with this aproach though is that anonymous functions won't survive compilation unless they are in the format of `&Foo.bar/arity`. One alternative is either go with {Mod, fun} or {Mod, fun, args}. Thoughts?

Patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index da4da6f1e..0f8cb7003 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -30,4 +30,4 @@ Phoenix v1.6 requires Elixir v1.9+.
 
 ## v1.5
 
-The CHANGELOG for v1.5 releases can be found [in the v1.5 branch](https://github.com/phoenixframework/phoenix/blob/v1.5/CHANGELOG.md).
+The CHANGELOG for v1.5 releases can be found in the [v1.5 branch](https://github.com/phoenixframework/phoenix/blob/v1.5/CHANGELOG.md).
diff --git a/README.md b/README.md
index 16726bdb7..a26c22e2a 100644
--- a/README.md
+++ b/README.md
@@ -17,7 +17,7 @@ Phoenix.js documentation is available at [https://hexdocs.pm/phoenix/js](https:/
 
 ## Contributing
 
-We appreciate any contribution to Phoenix. Check our [CODE_OF_CONDUCT.md](CODE_OF_CONDUCT.md) and [CONTRIBUTING.md](CONTRIBUTING.md) guides for more information. We usually keep a list of features and bugs [in the issue tracker][4].
+We appreciate any contribution to Phoenix. Check our [CODE_OF_CONDUCT.md](CODE_OF_CONDUCT.md) and [CONTRIBUTING.md](CONTRIBUTING.md) guides for more information. We usually keep a list of features and bugs in the [issue tracker][4].
 
 ### Generating a Phoenix project from unreleased versions
 
diff --git a/guides/controllers.md b/guides/controllers.md
index 1b5abd7d6..40c5450cd 100644
--- a/guides/controllers.md
+++ b/guides/controllers.md
@@ -131,7 +131,7 @@ It is worth noting that the `text/2`, `json/2`, and `html/2` functions require n
 
 The `json/2` function is obviously useful for writing APIs, and the other two may come in handy, but most of the times we use Phoenix views to build our responses. For this, Phoenix provides the `render/3` function.
 
-Let's rollback our `show` action to what we originally wrote [in the Request life-cycle guide](request_lifecycle.html):
+Let's rollback our `show` action to what we originally wrote in the [Request life-cycle guide](request_lifecycle.html):
 
 ```elixir
 defmodule HelloWeb.HelloController do
diff --git a/guides/deployment/releases.md b/guides/deployment/releases.md
index 8a96852bb..d61805d58 100644
--- a/guides/deployment/releases.md
+++ b/guides/deployment/releases.md
@@ -151,10 +151,7 @@ Elixir releases work well with container technologies, such as Docker. The idea
 Here is an example Docker file to run at the root of your application covering all of the steps above:
 
 ```docker
-FROM hexpm/elixir:1.11.2-erlang-23.1.2-alpine-3.12.1 as build
-
-# install build dependencies
-RUN apk add --no-cache build-base npm git python3
+FROM hexpm/elixir:1.11.2-erlang-23.1.2-alpine-3.12.1 as deps
 
 # prepare build dir
 WORKDIR /app
@@ -168,20 +165,25 @@ ENV MIX_ENV=prod
 
 # install mix dependencies
 COPY mix.exs mix.lock ./
-RUN mix deps.get --only $MIX_ENV
-RUN mkdir config
-# Dependencies sometimes use compile-time configuration. Copying
-# these compile-time config files before we compile dependencies
-# ensures that any relevant config changes will trigger the dependencies
-# to be re-compiled.
-COPY config/config.exs config/$MIX_ENV.exs config/
-RUN mix deps.compile
+RUN --mount=type=cache,target=/root/.hex \
+    mix deps.get --only $MIX_ENV
+
+FROM node:15.7.0-alpine3.10 as assets
+
+# install build dependencies
+RUN --mount=type=cache,sharing=locked,target=/var/cache/apk \
+    apk add build-base python
+
+# prepare build dir
+WORKDIR /app
 
 # build assets
 COPY assets/package.json assets/package-lock.json ./assets/
 # install all npm dependencies from scratch
 RUN npm --prefix ./assets ci --progress=false --no-audit --loglevel=error
 
+COPY --from=deps /app/deps ./deps
+
 COPY priv priv
 
 # Note: if your project uses a tool like https://purgecss.com/,
@@ -191,6 +193,21 @@ COPY priv priv
 COPY assets assets
 # use webpack to compile npm dependencies - https://www.npmjs.com/package/webpack-deploy
 RUN npm run --prefix ./assets deploy
+
+FROM deps as build
+
+# prepare build dir
+WORKDIR /app
+
+RUN mkdir config
+# Dependencies sometimes use compile-time configuration. Copying
+# these compile-time config files before we compile dependencies
+# ensures that any relevant config changes will trigger the dependencies
+# to be re-compiled.
+COPY config/config.exs config/$MIX_ENV.exs config/
+RUN mix deps.compile
+
+COPY --from=assets /app/priv ./priv
 RUN mix phx.digest
 
 # compile and build the release
@@ -205,7 +222,8 @@ RUN mix release
 # Start a new build stage so that the final image will only contain
 # the compiled release and other runtime necessities
 FROM alpine:3.12.1 AS app
-RUN apk add --no-cache openssl ncurses-libs
+RUN --mount=type=cache,sharing=locked,target=/var/cache/apk \
+    apk add openssl ncurses-libs
 
 WORKDIR /app
 
diff --git a/guides/plug.md b/guides/plug.md
index 49bda8c2a..9a0f96918 100644
--- a/guides/plug.md
+++ b/guides/plug.md
@@ -61,7 +61,7 @@ Host: "localhost"
 Headers: [...]
 ```
 
-Our Plug simply prints information from the connection. Although our initial Plug is very simple, you can virtually do anything you want inside of it. To learn about all fields available in the connection and all of the functionality associated to it, [see the documentation for Plug.Conn](https://hexdocs.pm/plug/Plug.Conn.html).
+Our Plug simply prints information from the connection. Although our initial Plug is very simple, you can virtually do anything you want inside of it. To learn about all fields available in the connection and all of the functionality associated to it, see the [documentation for Plug.Conn](https://hexdocs.pm/plug/Plug.Conn.html).
 
 Now let's look at the other flavor plugs come in, module plugs.
 
diff --git a/guides/realtime/presence.md b/guides/realtime/presence.md
index 028faa582..9f20d1f14 100644
--- a/guides/realtime/presence.md
+++ b/guides/realtime/presence.md
@@ -44,7 +44,7 @@ children = [
 ]
 ```
 
-Next we will create a channel that Presence can communicate on. For this example we will create a `RoomChannel` ([see the channels guide for more details on this](channels.html)):
+Next we will create a channel that Presence can communicate on. For this example we will create a `RoomChannel` (see the [channels guide](channels.html) for more details on this):
 
 ```console
 $ mix phx.gen.channel Room
diff --git a/guides/routing.md b/guides/routing.md
index ca36abedc..6592c9c16 100644
--- a/guides/routing.md
+++ b/guides/routing.md
@@ -693,7 +693,7 @@ forward "/jobs", BackgroundJob.Plug, name: "Hello Phoenix"
 
 There is a fourth `router_opts` argument that can be passed. These options are outlined in the `Phoenix.Router.scope/2` documentation.
 
-`BackgroundJob.Plug` can be implemented as any module plug discussed in the [Plug guide](plug.html). Note though it is not advised to forward to another Phoenix endpoint. This is because plugs defined by your app and the forwarded endpoint would be invoked twice, which may lead to errors.
+`BackgroundJob.Plug` can be implemented as any Module Plug discussed in the [Plug guide](plug.html). Note though it is not advised to forward to another Phoenix endpoint. This is because plugs defined by your app and the forwarded endpoint would be invoked twice, which may lead to errors.
 
 ## Summary
 
diff --git a/installer/templates/phx_assets/app.scss b/installer/templates/phx_assets/app.scss
index e76d9772b..c38ce37ce 100644
--- a/installer/templates/phx_assets/app.scss
+++ b/installer/templates/phx_assets/app.scss
@@ -34,7 +34,7 @@
 
 .phx-modal-content {
   background-color: #fefefe;
-  margin: 15% auto;
+  margin: 15vh auto;
   padding: 20px;
   border: 1px solid #888;
   width: 80%;
diff --git a/lib/mix/tasks/phx.gen.live.ex b/lib/mix/tasks/phx.gen.live.ex
index 8266b6585..f33cf6cba 100644
--- a/lib/mix/tasks/phx.gen.live.ex
+++ b/lib/mix/tasks/phx.gen.live.ex
@@ -16,8 +16,8 @@ defmodule Mix.Tasks.Phx.Gen.Live do
 
   When this command is run for the first time, a `ModalComponent` and
   `LiveHelpers` module will be created, along with the resource level
-  LiveViews and components, including an `IndexLive`, `ShowLive`, `FormComponent`
-  for the new resource.
+  LiveViews and components, including a `UserLive.Index`, `UserLive.Show`,
+  and `UserLive.FormComponent` for the new resource.
 
   > Note: A resource may also be split
   > over distinct contexts (such as `Accounts.User` and `Payments.User`).
@@ -31,9 +31,8 @@ defmodule Mix.Tasks.Phx.Gen.Live do
 
     * a context module in `lib/app/accounts.ex` for the accounts API
     * a schema in `lib/app/accounts/user.ex`, with a `users` table
-    * a view in `lib/app_web/views/user_view.ex`
-    * a LiveView in `lib/app_web/live/user_live/show_live.ex`
-    * a LiveView in `lib/app_web/live/user_live/index_live.ex`
+    * a LiveView in `lib/app_web/live/user_live/show.ex`
+    * a LiveView in `lib/app_web/live/user_live/index.ex`
     * a LiveComponent in `lib/app_web/live/user_live/form_component.ex`
     * a LiveComponent in `lib/app_web/live/modal_component.ex`
     * a helpers modules in `lib/app_web/live/live_helpers.ex`
diff --git a/lib/phoenix/logger.ex b/lib/phoenix/logger.ex
index fa96745c9..e87bfa42b 100644
--- a/lib/phoenix/logger.ex
+++ b/lib/phoenix/logger.ex
@@ -13,6 +13,7 @@ defmodule Phoenix.Logger do
       * Metadata: `%{conn: Plug.Conn.t, options: Keyword.t}`
       * Options: `%{log: Logger.level | false}`
       * Disable logging: In your endpoint `plug Plug.Telemetry, ..., log: Logger.level | false`
+      * Configure log level dynamically: `plug Plug.Telemetry, ..., log: {Mod, Fun, Args}`
 
     * `[:phoenix, :endpoint, :stop]` - dispatched by `Plug.Telemetry` in your
       endpoint whenever the response is sent
@@ -20,12 +21,14 @@ defmodule Phoenix.Logger do
       * Metadata: `%{conn: Plug.Conn.t, options: Keyword.t}`
       * Options: `%{log: Logger.level | false}`
       * Disable logging: In your endpoint `plug Plug.Telemetry, ..., log: Logger.level | false`
+      * Configure log level dynamically: `plug Plug.Telemetry, ..., log: {Mod, Fun, Args}`
 
     * `[:phoenix, :router_dispatch, :start]` - dispatched by `Phoenix.Router`
       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, pipe_through: [atom], log: Logger.level | false}`
       * Disable logging: Pass `log: false` to the router macro, for example: `get("/page", PageController, :index, log: false)`
+      * Configure log level dynamically: `get("/page", PageController, :index, log: {Mod, Fun, Args}`
 
     * `[:phoenix, :router_dispatch, :exception]` - dispatched by `Phoenix.Router`
       after exceptions on dispatching a route
@@ -85,6 +88,28 @@ 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.
 
+  ## Dynamic log level
+
+  In some cases you may wish to set the log level dynamically
+  on a per-request basis. To do so, set the `:log` option to
+  a tuple, `{Mod, Fun, Args}`. The `Plug.Conn.t()` for the
+  request will be prepended to the provided list of arguments.
+
+  When invoked, your function must return a
+  [`Logger.level()`](`t:Logger.level()/0`) or `false` to
+  disable logging for the request.
+
+  For example, in your Endpoint you might do something like this:
+
+        # lib/my_app_web/endpoint.ex
+        plug Plug.Telemetry,
+          event_prefix: [:phoenix, :endpoint],
+          log: {__MODULE__, :log_level, []}
+
+        # Disables logging for routes like /status/*
+        def log_level(%{path_info: ["status" | _]}), do: false
+        def log_level(_), do: :info
+
   ## Disabling
 
   When you are using custom logging system it is not always desirable to enable
@@ -167,15 +192,21 @@ defmodule Phoenix.Logger do
 
   defp keep_values(_other, _params), do: "[FILTERED]"
 
+  defp log_level(level, _conn) when is_atom(level), do: level
+
+  defp log_level({mod, fun, args}, conn) when is_atom(mod) and is_atom(fun) and is_list(args) do
+    apply(mod, fun, [conn | args])
+  end
+
   ## Event: [:phoenix, :endpoint, *]
 
   defp phoenix_endpoint_start(_, _, %{conn: conn} = metadata, _) do
-    case metadata[:options][:log] do
+    case log_level(metadata[:options][:log], conn) do
       false ->
         :ok
 
       level ->
-        Logger.log(level || :info, fn ->
+        Logger.log(level, fn ->
           %{method: method, request_path: request_path} = conn
           [method, ?\s, request_path]
         end)
@@ -183,12 +214,12 @@ defmodule Phoenix.Logger do
   end
 
   defp phoenix_endpoint_stop(_, %{duration: duration}, %{conn: conn} = metadata, _) do
-    case metadata[:options][:log] do
+    case log_level(metadata[:options][:log], conn) do
       false ->
         :ok
 
       level ->
-        Logger.log(level || :info, fn ->
+        Logger.log(level, fn ->
           %{status: status, state: state} = conn
           status = Integer.to_string(status)
           [connection_type(state), ?\s, status, " in ", duration(duration)]
@@ -225,10 +256,16 @@ defmodule Phoenix.Logger do
   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
+    %{log: level, conn: conn} = metadata
+    level = log_level(level, conn)
 
     Logger.log(level, fn ->
+      %{
+        pipe_through: pipe_through,
+        plug: plug,
+        plug_opts: plug_opts
+      } = metadata
+
       [
         "Processing with ",
         inspect(plug),


Test patch:
diff --git a/guides/testing/testing_channels.md b/guides/testing/testing_channels.md
index 39b3fbedc..2fe4b477b 100644
--- a/guides/testing/testing_channels.md
+++ b/guides/testing/testing_channels.md
@@ -57,7 +57,7 @@ defmodule HelloWeb.ChannelCase do
 end
 ```
 
-It is very straight-forward. It sets up a case template that imports all of `Phoenix.ChannelTest` on use. In the `setup` block, it starts the SQL Sandbox, which we discussed [in the Testing Contexts guide](testing_contexts.html).
+It is very straight-forward. It sets up a case template that imports all of `Phoenix.ChannelTest` on use. In the `setup` block, it starts the SQL Sandbox, which we discussed in the [Testing contexts guide](testing_contexts.html).
 
 ## Subscribe and joining
 
diff --git a/guides/testing/testing_controllers.md b/guides/testing/testing_controllers.md
index 44f692fc0..b2c6d965d 100644
--- a/guides/testing/testing_controllers.md
+++ b/guides/testing/testing_controllers.md
@@ -278,7 +278,7 @@ defmodule HelloWeb.ArticleView do
 end
 ```
 
-We talked about `render_many` [in the Views and Templates guide](views.html). All we need to know for now is that all JSON replies have a "data" key with either a list of posts (for index) or a single post inside of it.
+We talked about `render_many` in the [Views and templates guide](views.html). All we need to know for now is that all JSON replies have a "data" key with either a list of posts (for index) or a single post inside of it.
 
 Let's take a look at the test for the `index` action then:
 
@@ -382,7 +382,7 @@ end
 
 It simply posts to the `create` path with invalid parameters. This makes it return a JSON response, with status code 422, and a response with a non-empty "errors" key.
 
-The `action_fallback` can be extremely useful to reduce boilerplate when designing APIs. You can learn more about the "Action Fallback" [in the Controllers guide](controllers.html).
+The `action_fallback` can be extremely useful to reduce boilerplate when designing APIs. You can learn more about the "Action Fallback" in the [Controllers guide](controllers.html).
 
 ### The `delete` action
 
diff --git a/test/phoenix/endpoint/endpoint_test.exs b/test/phoenix/endpoint/endpoint_test.exs
index a70af1bd3..7c1c179ab 100644
--- a/test/phoenix/endpoint/endpoint_test.exs
+++ b/test/phoenix/endpoint/endpoint_test.exs
@@ -124,6 +124,42 @@ defmodule Phoenix.Endpoint.EndpointTest do
     assert_receive {^pid, :sample}
   end
 
+  test "invokes log level callback from Plug.Telemetry" do
+    defmodule TelemetryEndpoint do
+      use Phoenix.Endpoint, otp_app: :phoenix
+      plug Plug.Telemetry,
+        event_prefix: [:phoenix, :endpoint],
+        log: {__MODULE__, :log_level, []}
+
+      def log_level(conn) do
+        case conn.path_info do
+          [] -> :debug
+          ["warn" | _] -> :warn
+          ["error" | _] -> :error
+          _ -> :info
+        end
+      end
+    end
+
+    ExUnit.CaptureLog.capture_log(fn -> start_supervised! TelemetryEndpoint end)
+
+    assert ExUnit.CaptureLog.capture_log(fn ->
+      TelemetryEndpoint.call(conn(:get, "/"), [])
+    end) =~ "[debug] GET /"
+
+    assert ExUnit.CaptureLog.capture_log(fn ->
+      TelemetryEndpoint.call(conn(:get, "/warn"), [])
+    end) =~ "[warn]  GET /warn"
+
+    assert ExUnit.CaptureLog.capture_log(fn ->
+      TelemetryEndpoint.call(conn(:get, "/error/404"), [])
+    end) =~ "[error] GET /error/404"
+
+    assert ExUnit.CaptureLog.capture_log(fn ->
+      TelemetryEndpoint.call(conn(:get, "/any"), [])
+    end) =~ "[info]  GET /any"
+  end
+
   @tag :capture_log
   test "uses url configuration for static path" do
     Application.put_env(:phoenix, __MODULE__.UrlEndpoint, url: [path: "/api"])
@@ -177,7 +213,7 @@ defmodule Phoenix.Endpoint.EndpointTest do
 
   test "loads cache manifest from specified application" do
     config = put_in(@config[:cache_static_manifest], {:phoenix, "../../../../test/fixtures/digest/compile/cache_manifest.json"})
-    
+
     assert Endpoint.config_change([{Endpoint, config}], []) == :ok
     assert Endpoint.static_path("/foo.css") == "/foo-d978852bea6530fcd197b5445ed008fd.css?vsn=d"
   end
diff --git a/test/phoenix/router/routing_test.exs b/test/phoenix/router/routing_test.exs
index 93e3af42c..c76564bc6 100644
--- a/test/phoenix/router/routing_test.exs
+++ b/test/phoenix/router/routing_test.exs
@@ -23,6 +23,12 @@ defmodule Phoenix.Router.RoutingTest do
     def any(conn, _params), do: text(conn, "users any")
   end
 
+  defmodule LogLevel do
+    def log_level(%{params: %{"level" => "info"}}), do: :info
+    def log_level(%{params: %{"level" => "warn"}}), do: :warn
+    def log_level(_), do: :debug
+  end
+
   defmodule Router do
     use Phoenix.Router
 
@@ -48,6 +54,7 @@ defmodule Phoenix.Router.RoutingTest do
     end
 
     get "/no_log", SomePlug, [], log: false
+    get "/fun_log", SomePlug, [], log: {LogLevel, :log_level, []}
     get "/users/:user_id/files/:id", UserController, :image
     get "/*path", UserController, :not_found
 
@@ -221,6 +228,20 @@ defmodule Phoenix.Router.RoutingTest do
       refute capture_log(fn -> call(Router, :get, "/no_log", foo: "bar") end) =~
                "Processing with Phoenix.Router.RoutingTest.SomePlug"
     end
+
+    test "logs custom level when log is set to a 1-arity function" do
+      assert capture_log(fn -> call(Router, :get, "/fun_log", level: "info") end) =~
+               "[info]  Processing with Phoenix.Router.RoutingTest.SomePlug"
+
+      assert capture_log(fn -> call(Router, :get, "/fun_log", level: "warn") end) =~
+               "[warn]  Processing with Phoenix.Router.RoutingTest.SomePlug"
+
+      assert capture_log(fn -> call(Router, :get, "/fun_log", level: "yelling") end) =~
+               "[debug] Processing with Phoenix.Router.RoutingTest.SomePlug"
+
+      assert capture_log(fn -> call(Router, :get, "/fun_log") end) =~
+               "[debug] Processing with Phoenix.Router.RoutingTest.SomePlug"
+    end
   end
 
   test "route_info returns route string, path params, and more" do