plug_cowboy logger translator stopped working after upgrading to elixir version 1.15

[jviudes]

Elixir and Erlang/OTP versions

Erlang/OTP 26 [erts-14.1] [source] [64-bit] [smp:10:10] [ds:10:10:10] [async-threads:1]

Elixir 1.15.0 (compiled with Erlang/OTP 24)

Operating system

Sonoma 14.0

Current behavior

Logger translator doesn't seem to be sticking in plug_cowboy.

Inside Plug.Cowboy:

:logger.get_primary_config()

%{
  level: :debug,
  filters: [
    logger_process_level: {&Logger.Utils.process_level/2, []},
    logger_translator: {&Logger.Utils.translator/2,
     %{
       otp: true,
       sasl: false,
       translators: [
         {Plug.Cowboy.Translator, :translate},
         {Logger.Translator, :translate}
       ]
     }}
  ],
  filter_default: :log,
  metadata: %{}
}

Inside my Application:

:logger.get_primary_config()
%{
  level: :debug,
  filters: [
    logger_translator: {&Logger.Utils.translator/2,
     %{otp: true, sasl: false, translators: [{Logger.Translator, :translate}]}},
    logger_process_level: {&Logger.Utils.process_level/2, []}
  ],
  filter_default: :log,
  metadata: %{}
}

Expected behavior

Plug cowboy translator should be sticking out to the config. Application logger config should be:

:logger.get_primary_config()

%{
  level: :debug,
  filters: [
    logger_process_level: {&Logger.Utils.process_level/2, []},
    logger_translator: {&Logger.Utils.translator/2,
     %{
       otp: true,
       sasl: false,
       translators: [
         {Plug.Cowboy.Translator, :translate},
         {Logger.Translator, :translate}
       ]
     }}
  ],
  filter_default: :log,
  metadata: %{}
}

Plug cowboy translator works on Elixir version 1.14

[josevalim]

I cannot reproduce it on Elixir v1.16, so I suggest trying the latest Elixir v1.15 or latest Elixir v1.16.

[jviudes]

I still don't get the {Plug.Cowboy.Translator, :translate} on my logger config on version:
Erlang/OTP 26 [erts-14.1] [source] [64-bit] [smp:10:10] [ds:10:10:10] [async-threads:1]

Elixir 1.16.2 (compiled with Erlang/OTP 24)

[jviudes]

I don't know if that's the right place to be looking at, but logs started looking weird and leaking information that it shouldn't after I upgrade to elixir version 1.15. Just like plug_cowboy config isn't sticking.

[josevalim]

Can you provide steps to precisely reproduce this issue then? If I run iex -S mix inside plug_cowboy, I can see the translator. I can also see it in my apps.

[jviudes]

Yes, here's what I did:

• Start a new phoenix app on elixir 1.15 or greater (Or use this repo example I already started)
• Create a log exception. In my repo, I just added a raise "Error" on MyAppWeb.PageController.index/2.
• Call the endpoint curl --location 'http://localhost:4000' --header 'Authorization: Bearer this_i_dont_want_logged'
• Check log error message formatting. It will show something like this:

09:06:57.703 [error] Ranch listener MyAppWeb.Endpoint.HTTP, connection process #PID<0.597.0>, stream 1 had its request process #PID<0.598.0> exit with reason {{%RuntimeError{message: "Error"}, [{MyAppWeb.PageController, :index, 2, [file: ~c"lib/my_app_web/controllers/page_controller.ex", line: 5, error_info: %{module: Exception}]}, {MyAppWeb.PageController, :action, 2, [file: ~c"lib/my_app_web/controllers/page_controller.ex", line: 1]}, {MyAppWeb.PageController, :phoenix_controller_pipeline, 2, [file: ~c"lib/my_app_web/controllers/page_controller.ex", line: 1]}, {Phoenix.Router, :call, 2, [file: ~c"lib/phoenix/router.ex", line: 352]}, {MyAppWeb.Endpoint, :plug_builder_call, 2, [file: ~c"lib/my_app_web/endpoint.ex", line: 1]}, {MyAppWeb.Endpoint, :"call (overridable 3)", 2, [file: ~c"deps/plug/lib/plug/debugger.ex", line: 136]}, {MyAppWeb.Endpoint, :call, 2, [file: ~c"lib/my_app_web/endpoint.ex", line: 1]}, {Phoenix.Endpoint.Cowboy2Handler, :init, 4, [file: ~c"lib/phoenix/endpoint/cowboy2_handler.ex", line: 65]}, {:cowboy_handler, :execute, 2, [file: ~c"/Users/jhonathan/projects/podium/my_app/deps/cowboy/src/cowboy_handler.erl", line: 37]}, {:cowboy_stream_h, :execute, 3, [file: ~c"/Users/jhonathan/projects/podium/my_app/deps/cowboy/src/cowboy_stream_h.erl", line: 306]}, {:cowboy_stream_h, :request_process, 3, [file: ~c"/Users/jhonathan/projects/podium/my_app/deps/cowboy/src/cowboy_stream_h.erl", line: 295]}, {:proc_lib, :init_p_do_apply, 3, [file: ~c"proc_lib.erl", line: 241]}]}, {MyAppWeb.Endpoint, :call, [%Plug.Conn{adapter: {Plug.Cowboy.Conn, :...}, assigns: %{}, body_params: %Plug.Conn.Unfetched{aspect: :body_params}, cookies: %Plug.Conn.Unfetched{aspect: :cookies}, halted: false, host: "localhost", method: "GET", owner: #PID<0.598.0>, params: %Plug.Conn.Unfetched{aspect: :params}, path_info: [], path_params: %{}, port: 4000, private: %{}, query_params: %Plug.Conn.Unfetched{aspect: :query_params}, query_string: "", remote_ip: {127, 0, 0, 1}, req_cookies: %Plug.Conn.Unfetched{aspect: :cookies}, req_headers: [{"accept", "/"}, {"accept-encoding", "gzip, deflate, br"}, {"authorization", "Bearer this_i_dont_want_logged"}, {"cache-control", "no-cache"}, {"connection", "keep-alive"}, {"host", "localhost:4000"}, {"postman-token", "9b780c27-29ba-49f8-8821-578e0873763e"}, {"user-agent", "PostmanRuntime/7.37.0"}], request_path: "/", resp_body: nil, resp_cookies: %{}, resp_headers: [{"cache-control", "max-age=0, private, must-revalidate"}], scheme: :http, script_name: [], secret_key_base: nil, state: :unset, status: nil}, []]}} and stacktrace []

• Remove _build file and recompile using elixir 1.14
• Run the same curl command
• Check logs, it should show up something like this:

09:10:43.905 [error] #PID<0.4787.0> running MyAppWeb.Endpoint (connection #PID<0.4786.0>, stream id 1) terminated
Server: localhost:4000 (http)
Request: GET /
** (exit) an exception was raised:
** (RuntimeError) Error
(my_app 0.1.0) lib/my_app_web/controllers/page_controller.ex:5: MyAppWeb.PageController.index/2
(my_app 0.1.0) lib/my_app_web/controllers/page_controller.ex:1: MyAppWeb.PageController.action/2
(my_app 0.1.0) lib/my_app_web/controllers/page_controller.ex:1: MyAppWeb.PageController.phoenix_controller_pipeline/2
(phoenix 1.5.14) lib/phoenix/router.ex:352: Phoenix.Router.call/2
(my_app 0.1.0) lib/my_app_web/endpoint.ex:1: MyAppWeb.Endpoint.plug_builder_call/2
(my_app 0.1.0) deps/plug/lib/plug/debugger.ex:136: MyAppWeb.Endpoint."call (overridable 3)"/2
(my_app 0.1.0) lib/my_app_web/endpoint.ex:1: MyAppWeb.Endpoint.call/2
(phoenix 1.5.14) lib/phoenix/endpoint/cowboy2_handler.ex:65: Phoenix.Endpoint.Cowboy2Handler.init/4
(cowboy 2.12.0) /Users/jhonathan/projects/podium/my_app/deps/cowboy/src/cowboy_handler.erl:37: :cowboy_handler.execute/2
(cowboy 2.12.0) /Users/jhonathan/projects/podium/my_app/deps/cowboy/src/cowboy_stream_h.erl:306: :cowboy_stream_h.execute/3
(cowboy 2.12.0) /Users/jhonathan/projects/podium/my_app/deps/cowboy/src/cowboy_stream_h.erl:295: :cowboy_stream_h.request_process/3
(stdlib 4.3.1.3) proc_lib.erl:240: :proc_lib.init_p_do_apply/3

• This should be all to repro.

My point is that after upgrading my apps to elixir version 1.15 or greater, the plug_cowboy logger translator doesn't format the logs as it used to on version 1.14, which could cause some sensitive information to be leaked into the logs, like the request headers and token. I tried multiple approaches to get around this, like trying to specify a default_formatter, default_handler, and nothing seemed to work. The only thing that worked was to manually call Logger.add_translator({Plug.Cowboy.Translator, :translate}) in my Application file.

Could you please help me figure out why is that the case?

[jviudes]

Hey @josevalim , I just wanted to follow up and check if you had a chance to look at the above or had any idea on what might be happening. Thank you for your time

[josevalim]

Thank you, this has been fixed in Elixir and it will be part of the upcoming v1.16.x patch release as well.

[josevalim]

Fixed in b378a2d.

[jviudes]

Awesome, thanks a lot for looking into this!

[epinault]

@josevalim any chance we can get a 1.15 release? this is likely a risk for security concerns as they are a lot of stuff in the conn struct... And upgrading to 1.16 require fixing some hard deprecation for some of us. Feels like enough securityish concerns maybe to get a 1.15 patch too? what do you think?

[josevalim]

Assuming folks are using releases in production, I don’t believe the issue manifests inside a release, does it?

[epinault]

let s say not everyone uses mix release 😭 sometime people inherit things prior to use release and is a big undertaking but I am can see on a service that uses it maybe if that s an issue

[epinault]

@josevalim so the few we have are not yet in 1.15 :/ this feels still security patch related because other people may have translator that think that works . the patch is only few line and might be easy to add to 1.15 ?