Scope Log-level not working

[Dowwie]

Environment

• Elixir 1.14.4
• Phoenix 1.7.2
• Operating system: macos

Expected behavior

log: :debug defined at the scope-level should disable route logging when the log-level of the application is :info.

Actual behavior

scope-level logging continues to emit, regardless of the log option

[dinocosta]

Hey @Dowwie 👋

I am taking a look at this issue and wanted to first double-check if I understood your report correctly. I created a new phoenix app with the mix phx.new command and then updated the router module to use log: :debug on one of its scopes:

  scope "/", LoggingWeb, log: :debug do
    pipe_through :browser

    get "/", PageController, :home 
  end

Without changing the default log level in development, this is what I see when making a request to /:

After updating the log level to :info on config/dev.exs I can see that the debug message that was previously shown is now suppressed when visiting /:

What would be, for you, the expected behaviour here? Were you expecting that both the [info] GET/ and [info] Sent 200 in ... messages would be suppressed seeing as the endpoint is defined in the scope where log: :debug is being used?

Thanks!

P.S.: It looks like there's already a way to change log level per request according to Phoenix.Logger documentation, but it's separate from the :log option passed to the scope.

[Dowwie]

Messages in Slack older than 90 days cannot be referenced in free tier solutions, so unfortunately I can't point you to the discussion I had with Chris about this subject.

What would be, for you, the expected behaviour here? Were you expecting that both the [info] GET/ and [info] Sent 200 in ... messages would be suppressed seeing as the endpoint is defined in the scope where log: :debug is being used?

Yes, precisely. The situation I was working with was related to health checkpoints where ALB and K8s were flooding logging with probe requests. I wanted to quiet logging on those endpoints by setting the scope-level log-level of these health-check endpoints to :debug, but that wasn't achieving the desired effect even when setting application-level log-level, within /config, to :info.

[dinocosta]

Messages in Slack older than 90 days cannot be referenced in free tier solutions, so unfortunately I can't point you to the discussion I had with Chris about this subject.

What would be, for you, the expected behaviour here? Were you expecting that both the [info] GET/ and [info] Sent 200 in ... messages would be suppressed seeing as the endpoint is defined in the scope where log: :debug is being used?

Yes, precisely. The situation I was working with was related to health checkpoints where ALB and K8s were flooding logging with probe requests. I wanted to quiet logging on those endpoints by setting the scope-level log-level of these health-check endpoints to :debug, but that wasn't achieving the desired effect even when setting application-level log-level, within /config, to :info.

Thanks @Dowwie !

I just looked into how Phoenix logs this information and not sure if it's going to be a straightforward change. Both the message about the request verb and path (in my first message [info] GET /) as well as the response status code and duration (in my first message [info] Sent 200 in 33ms) are triggered by Plug.Telemetry, long story short:

• By default, Phoenix apps call plug Plug.Telemetry, event_prefix: [:phoenix, :endpoint] in the endpoint file
• This call to the Plug.Telemetry plug means that whenever a connection reaches that plug, it will emit the [:phoenix, :endpoint, :start] event, and just before returning the response it will emit the [:phoenix, :endpoint, :stop] event
• Both of the events above are captured by the Phoenix.Logger module, which uses the information in the %Plug.Conn{} struct to log those messages
• Since this plug is, by default, called before the router plug, I don't think it has access to information about the route and scope in order to sent it as metadata in the :telemetry.execute/3 calls here

I guess that, in order for something like this to work, we would probably need three changes:

1. Create a new plug to run before Plug.Telemetry, which would add information about the scope's :log option to the connection
2. Update Phoenix.Logger.phoenix_endpoint_start/4 to leverage this new information in order to determine the log level
3. Update Phoenix.Logger.phoenix_endpoint_stop/4 to leverage this new information in order to determine the log level

@chrismccord When you have some free time could you double-check if the suggested approach makes sense? Just want to make sure I'm not overlooking some important detail here, thanks!

[Gazler]

I wonder if we could attach the scope log value to the private section of the conn and then use it in Phoenix.Logger.phoenix_endpoint_stop/4 to override the log_level if the value is defined.

The Phoenix.Logger already supports a dynamic log level, which should probably take precedence over the scope level if it is defined.

https://hexdocs.pm/phoenix/Phoenix.Logger.html#module-dynamic-log-level

The log level can also be retrieved using something like:

Phoenix.Router.route_info(MyAppWeb.Router, "GET", "/", "localhost")

But if we plan on using it, I see no issue with storing the scope log level in there.

[dinocosta]

I wonder if we could attach the scope log value to the private section of the conn and then use it in Phoenix.Logger.phoenix_endpoint_stop/4 to override the log_level if the value is defined.

The Phoenix.Logger already supports a dynamic log level, which should probably take precedence over the scope level if it is defined.

https://hexdocs.pm/phoenix/Phoenix.Logger.html#module-dynamic-log-level

The log level can also be retrieved using something like:

Phoenix.Router.route_info(MyAppWeb.Router, "GET", "/", "localhost")

But if we plan on using it, I see no issue with storing the scope log level in there.

Thank you so much for chiming in @Gazler !

Yep, that's roughly the idea I was going for. I believe that should work for Phoenix.Logger.phoenix_endpoint_stop/4, as when that function is called, the connection should have already gone through the router module, where we can enrich the connections private fields with the scope's log level, however, Phoenix.Logger.phoenix_endpoint_start/4 is called before the connection reaches the router module.

Using Phoenix.Router.route_info/4 might work, but I guess that, if we want to call it inside Phoenix.Logger.phoenix_endpoint_start/4, we would need to know what's the router module beforehand 🤔

I'll take a stab at trying to update one of the existing modules (Phoenix.Endpoint or Phoenix.Router) in order to support this.

[Gazler]

I believe the logging only happens in the end function, so we don't need to know the router on the start event. It is available in conn.private btw. I think we still want the telemetry events to fire regardless of the log level.

…

On Thu, 14 Sept 2023, 15:16 Dino, ***@***.***> wrote: I wonder if we could attach the scope log value to the private section of the conn and then use it in Phoenix.Logger.phoenix_endpoint_stop/4 to override the log_level if the value is defined. The Phoenix.Logger already supports a dynamic log level, which should probably take precedence over the scope level if it is defined. https://hexdocs.pm/phoenix/Phoenix.Logger.html#module-dynamic-log-level The log level can also be retrieved using something like: Phoenix.Router.route_info(MyAppWeb.Router, "GET", "/", "localhost") But if we plan on using it, I see no issue with storing the scope log level in there. Thank you so much for chiming in @Gazler <https://github.com/Gazler> ! Yep, that's roughly the idea I was going for. I believe that should work for Phoenix.Logger.phoenix_endpoint_stop/4, as when that function is called, the connection should have already gone through the router module, where we can enrich the connections private fields with the scope's log level, however, Phoenix.Logger.phoenix_endpoint_start/4 is called before the connection reaches the router module. Using Phoenix.Router.route_info/4 might work, but I guess that, if we want to call it inside Phoenix.Logger.phoenix_endpoint_start/4, we would need to know what's the router module beforehand 🤔 I'll take a stab at trying to update one of the existing modules ( Phoenix.Endpoint or Phoenix.Router) in order to support this. — Reply to this email directly, view it on GitHub <#5463 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AADUSR6MLAKMO3KUHLQTJVTX2MGSHANCNFSM6AAAAAAYEBSFRU> . You are receiving this because you were mentioned.Message ID: ***@***.***>

[dinocosta]

I might be interpreting something here, so feel free to correct me, but looking at Phoenix.Logger.phoenix_endpoint_start/4 here, the Logger.log/2 function is being called to log information about the method and request path. I believe this is where the [info] GET / message in this screenshot gets logged.

These changes introduce a new private key to the connection, :phoenix_log_level, and update Phoenix.Logger.phoenix_endpoint_stop/4 to use that, in case :log is not present in the metadata options.

I'll see if I can come up with a way to also update the connection that reaches Phoenix.Logger.phoenix_endpoint_start/4 with this same information 👍

Thank you so much for the help so far!

[Gazler]

@dinocosta You are correct, there are two places log is called, I misremembered when I replied to you.

Unfortunately, log: :debug has never worked for the request level logging. It is specifically for the processing messages:

[debug] Processing with MyAppWeb.PageController.home/2
  Parameters: %{}
  Pipelines: [:browser]

Prior to the usage of telemetry, this was handled by the Plug.Logger, which also did not use the scope :log level.

It is certainly possible to support the use case here, however we already have a perfectly good way of filtering out specific routes.

I believe the best course of action here is to leave everything as it is and improve the documentation.

Specifically in these locations:

https://hexdocs.pm/phoenix/Phoenix.Router.html#scope/2
https://hexdocs.pm/phoenix/Phoenix.Router.html#route_info/4

Currently it says:

:log - the level to log the route dispatching under, may be set to false. Defaults to :debug

However it is unclear what route dispatching really is. We should clarify with something like:

:log - the level to log the route dispatching under, may be set to false. Defaults to :debug. Route dispatching contains information about how the route is handled, and is separate from the plug level logging. To alter the plug log level, please see https://hexdocs.pm/phoenix/Phoenix.Logger.html#module-dynamic-log-level.

I appreciate the effort you have put into this so far, and a PR to improve the docs would be most welcome.

[dinocosta]

It is certainly possible to support the use case here, however we already have a perfectly good way of filtering out specific routes.

I believe the best course of action here is to leave everything as it is and improve the documentation.

Have to agree with you here, especially because the Phoenix.Router.Scope struct already defaults the :log field to :debug, so we would even need to add extra code to actually validate if the :log option was actually provided, and not simply propagate the :log field from the scope.

I will open a Merge Request with the updated documentation, thank you for the suggestion and help 👍

[dinocosta]

@Gazler I've opened a Pull Request updating the documentation - #5580 .

A couple of things worth noting:

• I didn't update the documentation for https://hexdocs.pm/phoenix/Phoenix.Router.html#route_info/4 as the function does not actually support a list of options, it just mentions the :log field present in the map returned by this function.
• The Pull Request also updates the documentation for Phoenix.Router.match/5 as, if I am not mistaken, the :log option can also be defined by route. For example, get "/", AppWeb.PageController, :home, log: :info.

Let me know if any of the points above don't make sense or if you have any other suggestions, I'll gladly update my Pull Request.

Thanks!