JWT authn: Logging for cache refresh for JWKS

[aniketmasule]

Title: Logging for cache refresh for JWKS

Description: I am using jwt filter for authentication, using remote_jwks to provide remote jwks uri and using cache_duration to configure cache refresh interval. I have a query regarding following scenario: When rotating signing keys, we begin by advertising the new key's on remote URI. Then, we activate it, and new tokens are signed with these new keys. However, I'm unable to determine if the new key has been cached successfully before activating new keys. Is there a method to log the cached keys or somehow check the cache? Additionally, I cannot obtain tokens with the new key until I activate the new signing keys.

Relevant Links: https://www.envoyproxy.io/docs/envoy/latest/configuration/http/http_filters/jwt_authn_filter#config-http-filters-jwt-authn

[phlax]

cc @taoxuy @lizan

[aniketmasule]

Hi @TAOXUY @lizan, Kindly let me know if you have any inputs on above query?

[aniketmasule]

Hi @TAOXUY , @lizan , Could you please let me know if there is an existing way to handle the above mentioned scenario? Any input would be greatly appreciated. Thank you

[arulthileeban]

AFAIK there is no straightforward way to look into the cache. An indirect way would be to investigate debug logs. They would produce similar logs as below which would indicate when a new JWKS is retrieved.

Note that, in the current state, the JWT filter will not intelligently try to retrieve a new JWKS if all requests coming in are signed with a different KID (the rotated key) #14557 . It will only retrieve it when the cache duration expires

[2024-06-02 15:45:48.395][4898852][debug][init] [source/common/init/target_impl.cc:15] init manager Listener-local-init-manager 5c8e57c5-6e81-4084-8c4b-ed58a6427ec3 1236881589127937490 initializing target Jwks async fetching url=https://localhost:8080/.well-known/jwks.json
[2024-06-02 15:45:48.395][4898852][debug][jwt] [source/extensions/filters/http/jwt_authn/jwks_async_fetcher.cc:86] Jwks async fetching url=https://localhost:8080/.well-known/jwks.json: started
[2024-06-02 15:45:48.395][4898852][debug][filter] [source/extensions/filters/http/common/jwks_fetcher.cc:60] fetch pubkey from [uri = https://localhost:8080/.well-known/jwks.json]: start
[2024-06-02 15:45:48.396][4898852][debug][router] [source/common/router/router.cc:515] [Tags: "ConnectionId":"0","StreamId":"518139968505146129"] cluster 'local_oidc' match for URL '/.well-known/jwks.json'
[2024-06-02 15:45:48.396][4898852][debug][router] [source/common/router/router.cc:738] [Tags: "ConnectionId":"0","StreamId":"518139968505146129"] router decoding headers:
':path', '/.well-known/jwks.json'
':authority', 'localhost:8080'
':method', 'GET'
':scheme', 'http'
'x-envoy-internal', 'true'
'x-forwarded-for', '192.168.25.226'
'x-envoy-expected-rq-timeout-ms', '5000'

[2024-06-02 15:45:48.396][4898852][debug][pool] [source/common/http/conn_pool_base.cc:78] queueing stream due to no available connections (ready=0 busy=0 connecting=0)
[2024-06-02 15:45:48.396][4898852][debug][pool] [source/common/conn_pool/conn_pool_base.cc:291] trying to create new connection
[2024-06-02 15:45:48.396][4898852][debug][pool] [source/common/conn_pool/conn_pool_base.cc:145] creating a new connection (connecting=0)
[2024-06-02 15:45:48.397][4898852][debug][connection] [./source/common/network/connection_impl.h:98] [Tags: "ConnectionId":"0"] current connecting state: true
[2024-06-02 15:45:48.397][4898852][debug][client] [source/common/http/codec_client.cc:57] [Tags: "ConnectionId":"0"] connecting
[2024-06-02 15:45:48.397][4898852][debug][connection] [source/common/network/connection_impl.cc:1017] [Tags: "ConnectionId":"0"] connecting to 127.0.0.1:8080
[2024-06-02 15:45:48.397][4898852][debug][connection] [source/common/network/connection_impl.cc:1036] [Tags: "ConnectionId":"0"] connection in progress
[2024-06-02 15:45:48.397][4898852][debug][connection] [source/common/network/connection_impl.cc:746] [Tags: "ConnectionId":"0"] connected
[2024-06-02 15:45:48.397][4898852][debug][client] [source/common/http/codec_client.cc:88] [Tags: "ConnectionId":"0"] connected
[2024-06-02 15:45:48.397][4898852][debug][pool] [source/common/conn_pool/conn_pool_base.cc:328] [Tags: "ConnectionId":"0"] attaching to next stream
[2024-06-02 15:45:48.397][4898852][debug][pool] [source/common/conn_pool/conn_pool_base.cc:182] [Tags: "ConnectionId":"0"] creating stream
[2024-06-02 15:45:48.397][4898852][debug][router] [source/common/router/upstream_request.cc:588] [Tags: "ConnectionId":"0","StreamId":"518139968505146129"] pool ready
[2024-06-02 15:45:48.397][4898852][debug][client] [source/common/http/codec_client.cc:142] [Tags: "ConnectionId":"0"] encode complete
[2024-06-02 15:45:48.416][4898852][debug][router] [source/common/router/router.cc:1530] [Tags: "ConnectionId":"0","StreamId":"518139968505146129"] upstream headers complete: end_stream=false
[2024-06-02 15:45:48.416][4898852][debug][http] [source/common/http/async_client_impl.cc:134] async http request response headers (end_stream=false):
':status', '200'
'content-type', 'application/json'
'date', 'Sun, 02 Jun 2024 19:45:48 GMT'
'content-length', '478'
'x-envoy-upstream-service-time', '18'

[2024-06-02 15:45:48.416][4898852][debug][client] [source/common/http/codec_client.cc:129] [Tags: "ConnectionId":"0"] response complete
[2024-06-02 15:45:48.416][4898852][debug][filter] [source/extensions/filters/http/common/jwks_fetcher.cc:85] onSuccess: fetch pubkey [uri = https://localhost:8080/.well-known/jwks.json]: success
[2024-06-02 15:45:48.416][4898852][debug][filter] [source/extensions/filters/http/common/jwks_fetcher.cc:91] onSuccess: fetch pubkey [uri = https://localhost:8080/.well-known/jwks.json]: succeeded

[github-actions[bot]]

This issue has been automatically marked as stale because it has not had activity in the last 30 days. It will be closed in the next 7 days unless it is tagged "help wanted" or "no stalebot" or other activity occurs. Thank you for your contributions.

[github-actions[bot]]

This issue has been automatically closed because it has not had activity in the last 37 days. If this issue is still valid, please ping a maintainer and ask them to label it as "help wanted" or "no stalebot". Thank you for your contributions.