Log level not respected, follows default Logger level regardless of configuration

[eprothro]

Regardless of either of the documented configurations for log level:

# lib/app/apple_strategy.ex
defmodule App.AppleStrategy do
  use JokenJwks.DefaultStrategyTemplate

  def init_opts(opts) do
    url = "https://appleid.apple.com/auth/keys"
    Keyword.merge(opts, jwks_url: url, log_level: :warn)
  end
end

# config/config.exs
config :joken_jwks,
  log_level: :warn

The logs emitted follow the Logger.level, debug shown below:

[info] GET https://appleid.apple.com/auth/keys -> 200 (572.966 ms)
[debug]
>>> REQUEST >>>
(no query)
(no headers)
(no body)

<<< RESPONSE <<<
server: Apple
date: Thu, 15 Sep 2022 13:27:25 GMT
content-type: application/json;charset=ISO-8859-1
content-length: 1439
connection: keep-alive
cache-control: no-store
pragma: no-cache
access-control-allow-origin: *

{
  "keys": [
    {
      "kty": "RSA",
      "kid": "W6WcOKB",
      "use": "sig",
      "alg": "RS256",
      "n": "2Zc5d0-zkZ5AKmtYTvxHc3vRc41YfbklflxG9SWsg5qXUxvfgpktGAcxXLFAd9Uglzow9ezvmTGce5d3DhAYKwHAEPT9hbaMDj7DfmEwuNO8UahfnBkBXsCoUaL3QITF5_DAPsZroTqs7tkQQZ7qPkQXCSu2aosgOJmaoKQgwcOdjD0D49ne2B_dkxBcNCcJT9pTSWJ8NfGycjWAQsvC8CGstH8oKwhC5raDcc2IGXMOQC7Qr75d6J5Q24CePHj_JD7zjbwYy9KNH8wyr829eO_G4OEUW50FAN6HKtvjhJIguMl_1BLZ93z2KJyxExiNTZBUBQbbgCNBfzTv7JrxMw",
      "e": "AQAB"
    },
    {
      "kty": "RSA",
      "kid": "YuyXoY",
      "use": "sig",
      "alg": "RS256",
      "n": "1JiU4l3YCeT4o0gVmxGTEK1IXR-Ghdg5Bzka12tzmtdCxU00ChH66aV-4HRBjF1t95IsaeHeDFRgmF0lJbTDTqa6_VZo2hc0zTiUAsGLacN6slePvDcR1IMucQGtPP5tGhIbU-HKabsKOFdD4VQ5PCXifjpN9R-1qOR571BxCAl4u1kUUIePAAJcBcqGRFSI_I1j_jbN3gflK_8ZNmgnPrXA0kZXzj1I7ZHgekGbZoxmDrzYm2zmja1MsE5A_JX7itBYnlR41LOtvLRCNtw7K3EFlbfB6hkPL-Swk5XNGbWZdTROmaTNzJhV-lWT0gGm6V1qWAK2qOZoIDa_3Ud0Gw",
      "e": "AQAB"
    },
    {
      "kty": "RSA",
      "kid": "fh6Bs8C",
      "use": "sig",
      "alg": "RS256",
      "n": "u704gotMSZc6CSSVNCZ1d0S9dZKwO2BVzfdTKYz8wSNm7R_KIufOQf3ru7Pph1FjW6gQ8zgvhnv4IebkGWsZJlodduTC7c0sRb5PZpEyM6PtO8FPHowaracJJsK1f6_rSLstLdWbSDXeSq7vBvDu3Q31RaoV_0YlEzQwPsbCvD45oVy5Vo5oBePUm4cqi6T3cZ-10gr9QJCVwvx7KiQsttp0kUkHM94PlxbG_HAWlEZjvAlxfEDc-_xZQwC6fVjfazs3j1b2DZWsGmBRdx1snO75nM7hpyRRQB4jVejW9TuZDtPtsNadXTr9I5NjxPdIYMORj9XKEh44Z73yfv0gtw",
      "e": "AQAB"
    }
  ]
}

[victorolinasc]

Sorry I took a long time to reply here...

This is particularly strange... we have tests for exactly this case. Most of the time log levels are evaluated at compile time so, just to be sure, have you tried recompile the dependency once changing the log level?

In any case, I've decided to move away from custom logging in libraries... from Elixir 1.12+ it makes less sense... We can set levels for specific modules or whole applications with Logger.put_application_level/2 and so on.

This will be included in a next major version.

[eprothro]

Thanks for the response! That could make sense as our application log level is set a runtime. However as shown above, the joken log level is set at compile time, and I would have expected that to override application level.

Would certainly prefer to see telemetry over application logging!

[rogerweb]

@eprothro , did you end up sorting it out?

I've tried adding the following line to my runtime.exs but it had no effect:

Logger.put_module_level(MyApp.MyStrategy, :warning)

I also tried like this (adding the .EtsCache), with no success either:

Logger.put_module_level(MyApp.MyStrategy.EtsCache, :warning)

I also tried those in an iex session, with no luck.

Then I gave up trying to change it during runtime and tried to set it in my config.exs, with no luck again:

config :logger,
  compile_time_purge_matching: [
    [module: MyApp.MyStrategy, level_lower_than: :warning]
  ]

Same thing with .EtsCache.

I'm not familiar with macros, so I also tried those with JokenJwks.DefaultStrategyTemplate.EtsCache instead because not sure what happens first. But no luck either. Any help would be much appreciated.

[eprothro]

@rogerweb nope still cluttering our logs, just hasn't been the priority.

[victorolinasc]

I will look at it more closely now. Sorry for the long delay in support here... I have a complete pure Elixir JOSE replacement for JWS and was half way through JWE but life just took all my time in the last months...

I will see if I can reproduce locally, fix it and release a new version ASAP.

[victorolinasc]

I've opened #47 . Can any of you try it before releasing a new version?

[rogerweb]

Can any of you try it before releasing a new version?

Successfully tested within my application, capturing the following events:

[:joken_jwks, :default_strategy, :signers],
[:joken_jwks, :http_fetcher, :start],
[:joken_jwks, :http_fetcher, :stop]

Couldn't test the other two though:

[:joken_jwks, :default_strategy, :refetch],
[:joken_jwks, :http_fetcher, :exception]

Thanks for the quick turn around!

[victorolinasc]

:refetch should trigger when you send a bad token... try feeding the api something like "a.b.c" and see if it trigges then.

:exception will only trigger if the http channel somehow raises (like :econnrefused and friends)

[rogerweb]

Managed to trigger the :refetch but no success simulating the :exception. Tried 3 scenarios only:

(1) network cable unplugged (2) invalid domain in the JWKS URL (3) JWKS URL returning 404

(1) and (2) resulted in an error message in the log but no telemetry event:

[error] Failed to fetch signers. Reason: {:error, :nxdomain}

(3) resulted in an error message in the log but no telemetry event:

[error] Failed to fetch signers. Reason: {:error, :jwks_client_http_error}

I'm fine with the current behavior.

[victorolinasc]

Thanks for trying it out @rogerweb . I will add some test cases here and merge it :)

[victorolinasc]

The new approach with telemetry is on master (which I will rename to main non next release) and will be on next release.

Thanks all for the input!