Phoenix: Phoenix.Controller `:log` option no longer respected in v1.4.7+

[topherhunt]

In <= v1.4.6, when you use Phoenix.Controller e.g. in the autogenerated my_app_web.ex file, you could set a :log option that would either set the log level for controller-related console output, or disable it altogether. In v1.4.7 to v1.4.9, this :log option is no longer respected even though the docs still say it should work as it previously did.

I'm guessing this has something to do with the move towards Elixir telemetry.

Environment

• Elixir version (elixir -v): 1.8.1
• Phoenix version (mix deps): 1.4.9
• NodeJS version (node -v): 8.9.3
• NPM version (npm -v): 6.10.1
• Operating system: Mac OSX 10.14.4

Expected behavior

When using Phoenix.Controller, (e.g. use Phoenix.Controller, namespace: MyAppWeb, log: false), the :log option should impact what output appears in the console.

Actual behavior

The :log option doesn't appear to have any effect, whether I set it to false or a log level atom like :info.

Repro steps

• mix phx.new my_app (say yes to dependencies)
• cd my_app
• mix ecto.create

• In lib/my_app_web.ex), set the :log option to false (or any other valid setting):

  use Phoenix.Controller, namespace: MyAppWeb, log: false
  

• mix phx.server

• Load the homepage in a browser. In the console, you'll see the Phoenix.Controller log output in the debug level, even though the log: false setting should have disabled it.

[alexgaribay]

@chrismccord @josevalim With the recent migration to using telemetry, it looks like logging is set by the routes within the router via the various HTTP verbs macros and scope macro. I can add code to account for what the Controller log option is but it poses a conflict of which log level should have precedence. For instance:

• scope is set to :info but controller is false
• route is set to false but controller is :warn

[josevalim]

We can't load the controller code from the router unfortunately, that would cause a deadlock during compilation.

@topherhunt you should consider the route logging as a complete separate logger, because both are available on v1.4 (although the controller one is now disabled out of the box). So you need to disable it in the router too. It would be the same if we added some logging when rendering a view, if you don't want it, you would have to disable it there. So the best course of action is to disable in both places. Sorry for the confusion!

[topherhunt]

Thanks guys.

For anyone else who finds this: to disable those logs, I first got a list of attached handlers by calling :telemetry.list_handlers([]), then in MyApp.Application.start/2 I detached the handlers for each log entry that I wanted to hide:

def start(_type, _args) do
  # ...

  :ok = :telemetry.detach({Phoenix.Logger, [:phoenix, :socket_connected]})
  :ok = :telemetry.detach({Phoenix.Logger, [:phoenix, :channel_joined]})
  :ok = :telemetry.detach({Phoenix.Logger, [:phoenix, :router_dispatch, :start]})

  # ...
  Supervisor.start_link(children, opts)
end

[simpers]

If I'm not mistaken, as I fiddled with this previously, I can no longer disable just one controller, which in my case is the health controller for my kubernetes probes. I do want to keep the other tidbits of the functionality, like the duration telemetry and such, just not the log itself as it clutters the logs when kubernetes probes every x seconds.

How would I go about doing this without recreating said behaviour for this one controller but as a stand-alone plug, which is the advice I have gotten before.

[josevalim]

Controllers no longer log, you can now disable it with a flag on the router.

[alexcastano]

Controllers no longer log, you can now disable it with a flag on the router.

Controllers no longer log, right, and you can disable [:phoenix, :router_dispatch, :start] logs with the log: false in the router macro. However, the [:phoenix, :endpoint, :start | :stop] cannot be disabled for a single (or multiple) routes. AFAIK you have all the endpoint logs for all routes or for none.

The only solution I found is to disable all of them, and copy the Phoenix.Logger in my project with small modifications to avoid logs some routes. I disabled the k8s /health one for instance, which cluttered the logs every 2 seconds. Before, you could achieve this behaviour just moving the Plug.Logger to the right pipelines.

Do you think is a good idea for a PR a new option for Plug.Telemetry--similar to the :log one--to avoid logging some routes? Maybe exclude_paths: ["strings", ~r/regex/] or exclude_paths: &predicate/1?

Thank you!

[josevalim]

You can wrap Plug.Telemetry by calling it via your own function. Instead of plug Plug.Telemetry, do:

plug :telemetry

where:

def telemetry(conn, opts) do
  Plug.Telemetry.call(conn, Plug.Telemetry.init(opts))
end

Now you can match it so it runs whenever you want.

[alexcastano]

I didn't think about :man_facepalming:

For my use case, it works perfectly. However, a possible concern for other people is that maybe you only want to deactivate logs but not other :telemetry hooks.

Thanks a lot for your time