APM/OAuth2 : auto apply changes made by discovery

Hi Lucas,

Thanks for your valuable help. Support Case has been openned and linked to this thread !

I'll update when a solution is found!

Regards,

Olivier

So, there has been a change in the JWT this week-end on Azure Entra, and I got a lot of logs from restjavad.

I won't post the part where it discovers the new JWTs, delete the old jwt/certs in the config, create the new one, and skip to the SAVE_AND_APPLY phase of OIDCDiscoverTask. (I also stripped the begining of the lines for readability)

All lines start with [F][21133][25 Aug 2024 18:25:27 UTC][8100/tm/access/oidc/discover OIDCDiscoverTaskCollectionWorker]

[18:25:26] install meta data  sending mcp request
[18:25:26] intall meta dataa  sending mcp request
[18:25:27] OIDC Discover provider name is /HES-SO/HES_AGF_AzAD_Provider and step SAVE_AND_APPLY
[18:25:27] saveAndApply :mcpProviderName /HES-SO/HES_AGF_AzAD_Provider 
[18:25:27] applyPolicyForProvider chain >> 
[18:25:27] applyPolicyForProvider chain >> 
[18:25:27] applyPolicyForProvider total items in chains = 2
[18:25:27] setup doChainQuery queries : chain >> 
[18:25:27] do chain query with names [/HES-SO/HES_AGF_AzAD_Provider], remaining step 5
[18:25:27] setup mcp queryAll for name /HES-SO/HES_AGF_AzAD_Provider qi = 
[18:25:27] setup doChainQuery queries : chain >> 
[18:25:27] do chain query with names [/HES-SO/HES_AGF_AzAD_Provider], remaining step 5
[18:25:27] setup mcp queryAll for name /HES-SO/HES_AGF_AzAD_Provider qi = 
[18:25:27] mcpOperation queryInfo=
[18:25:27] results from mcp-multi requests /HES-SO/HES_AGF_M365_JWTP,  for queryInfo = 
[18:25:27] do chain query with names [/HES-SO/HES_AGF_M365_JWTP], remaining step 4
[18:25:27] setup mcp queryAll for name /HES-SO/HES_AGF_M365_JWTP qi = 
[18:25:28] mcpOperation queryInfo=
[18:25:28] results from mcp-multi requests /HES-SO/HES_AGF_OAuth_Srv,  for queryInfo = 
[18:25:28] do chain query with names [/HES-SO/HES_AGF_OAuth_Srv], remaining step 4
[18:25:28] setup mcp queryAll for name /HES-SO/HES_AGF_OAuth_Srv qi = 
[18:25:28] mcpOperation queryInfo=
[18:25:28] results from mcp-multi requests  for queryInfo = 
[18:25:28] applyPolicyForProvider handling of a chain
[18:25:28] mcpOperation queryInfo=
[18:25:28] results from mcp-multi requests /HES-SO/HES_AGF_M365_act_oauth_client_ag,  for queryInfo = 
[18:25:28] do chain query with names [/HES-SO/HES_AGF_M365_act_oauth_client_ag], remaining step 3
[18:25:28] setup mcp queryAll for name /HES-SO/HES_AGF_M365_act_oauth_client_ag qi = 
[18:25:28] mcpOperation queryInfo=
[18:25:28] results from mcp-multi requests /HES-SO/HES_AGF_M365_act_oauth_client,  for queryInfo = 
[18:25:28] do chain query with names [/HES-SO/HES_AGF_M365_act_oauth_client], remaining step 2
[18:25:28] setup mcp queryAll for name /HES-SO/HES_AGF_M365_act_oauth_client qi = 
[18:25:28] mcpOperation queryInfo=
[18:25:28] policyName = /HES-SO/HES_AGF_M365, resolvedPolicyName = null
[18:25:28] results from mcp-multi requests null,  for queryInfo = 
[18:25:28] applyPolicyForProvider handling of a chain
[18:25:28] aps is empty.
[18:25:28] OIDC Discover provider name is /HES-SO/HES_AGF_AzAD_Provider and step SLEEP_AND_RUN_AGAIN
[18:25:28] Task ID 3394e5d4-9c7d-4685-808d-738c16e11dc8 for provider /HES-SO/HES_AGF_AzAD_Provider has completed one round, we will schedule the next discover after 1440 minutes

Lines 36-39 looks odd.

and sill no trace of "generation-action increment" in audit log.

Thanks for your help !
I have enabled the Fine log level for restjavad.

I also found this entry in /var/log/apm but the timestamp match the time when I applied the policy manually.

Aug 23 09:52:16 f5-moz.mgmt.hefr.ch notice apmd[14720]: 01490165:5: Access profile: /HES-SO/HES_AGF_M365 initialized with configuration snapshot catalog: tmm.session.f5f5f5f5f5f5f5f5f5f5f5f5f5f5f5f5
Aug 23 09:52:17 f5-moz.mgmt.hefr.ch notice apmd[14720]: 01490166:5: Current snapshot ID: 1697025208 retrieved from session db for access profile: /HES-SO/HES_AGF_M365
Aug 23 09:52:17 f5-moz.mgmt.hefr.ch notice apmd[14720]: 0149016a:5: Initiating snapshot creation: tmm.session.139d3f1399a5174_18oooooooooooooo for access profile: /HES-SO/HES_AGF_M365
Aug 23 09:52:17 f5-moz.mgmt.hefr.ch notice apmd[14720]: 0149016b:5: Completed snapshot creation: tmm.session.139d3f1399a5174_18oooooooooooooo for access profile: /HES-SO/HES_AGF_M365
Aug 23 09:52:17 f5-moz.mgmt.hefr.ch notice apmd[14720]: 01490167:5: Current snapshot ID: 1697025209 updated inside session db for access profile: /HES-SO/HES_AGF_M365

So now I just have to wait for a new change to happen in Azure to trigger a change by the discovery process !

Thanks for your valuable help !

Interesting... So we know restjavad is at least scheduled and not throwing errors.

By default the logging for that process is sparse and won't log much about success operations. It does log information about Apply at "FINE" logging level. It can be adjusted by editing the file /etc/restjavad.log.conf. The logging configuration line should be added at the end so it’s not overridden by a later setting.

1-      SSH to the BIG-IP.

2-      Edit /etc/restjavad.log.conf

3-      Add the line at the end, for FINE level verbosity:

com.f5.rest.tmos.bigip.access.openid.OIDCDiscoverTaskCollectionWorker.level=FINE

4-      bigstart restart restjavad.

These logging levels are available:

• SEVERE (highest value)
• WARNING
• INFO (this is default)
• CONFIG
• FINE
• FINER
• FINEST (lowest value)

There are also some other evidence that Apply has been performed:

1- /var/log/apm will have information about updating the "snapshot" version, which is APMd's data-structure of the access policy and its config objects.

2- /var/log/audit will have traces of a command "generation-action increment" and should have some detailed info.

I'm not sure we can get this all resolved with forum posts, but it's good information to understand the issue and symptoms more fully.

Hi Lucas,

Thanks for this very helpful answer.

So for example this morning at 06:55 the discovery process updated the configuration. (I also run a diff of the config on my f5 every 15 minutes and any change are reported by mail and in a git repository).

In the logs I found :

[I][2402045][23 Aug 2024 06:55:15 UTC][8100/tm/access/oidc/discover OIDCDiscoverTaskCollectionWorker] Downloading OpenID metadata for provider /HES-SO/HES_AGF_AzAD_Provider task ID 3394e5d4-9c7d-4685-808d-738c16e11dc8 using OpenID URI https://login.microsoftonline.com/a372f724-c0b2-4ea0-abfb-0eb8c6f84e40/v2.0/.well-known/openid-configuration and Trusted CA Bundle /Common/ca-bundle.crt
[I][2402048][23 Aug 2024 06:55:17 UTC][8100/tm/access/oidc/discover OIDCDiscoverTaskCollectionWorker] Updating mcp jwt and jwk objects for provider /HES-SO/HES_AGF_AzAD_Provider task ID 3394e5d4-9c7d-4685-808d-738c16e11dc8
[I][2402049][23 Aug 2024 06:55:17 UTC][8100/tm/access/oidc/discover OIDCDiscoverTaskCollectionWorker] Task ID 3394e5d4-9c7d-4685-808d-738c16e11dc8 for provider /HES-SO/HES_AGF_AzAD_Provider has completed one round, we will schedule the next discover after 1440 minutes

We can see that the jwt configuration has been updated.

Here's the config diff 

diff --git a/f5-moz b/f5-moz
index 243ed0c9..a426214b 100644
--- a/f5-moz
+++ b/f5-moz
@@ -43168,7 +43168,7 @@
 #     auto-jwt-config-name /HES-SO/auto_jwt_HES_AGF_AzAD_Provider
 #     discovery-interval 1440
 #     introspect unsupported
-#     last-discovery-time 2024-08-18:08:54:54
+#     last-discovery-time 2024-08-23:08:55:16
 #     openid-cfg-uri https://login.microsoftonline.com/a372f724-c0b2-4ea0-abfb-0eb8c6f84e40/v2.0/.well-known/openid-configuration
 #     token-uri https://login.microsoftonline.com/a372f724-c0b2-4ea0-abfb-0eb8c6f84e40/oauth2/v2.0/token
 #     trusted-ca-bundle /Common/ca-bundle.crt
@@ -43178,7 +43178,7 @@
 # apm aaa oauth-server /HES-SO/HES_AGF_OAuth_Srv {
 #     client-id <<redacted>>
 #     client-jwe-key /HES-SO/auto_jwk_HES_AGF_AzAD_Provider1
-#     client-secret <<redacted>>
+#     client-secret <<redacted>>
 #     client-serverssl-profile-name /Common/serverssl-insecure-compatible
 #     dns-resolver-name /Common/IB-Resolver
 #     provider-name /HES-SO/HES_AGF_AzAD_Provider
@@ -43223,12 +43223,23 @@
 #     modulus <<redacted>>
 #     public-exponent AQAB
 # }
+# apm oauth jwk-config /HES-SO/auto_jwk_HES_AGF_AzAD_Provider5 {
+#     auto-generated true
+#     cert /HES-SO/auto_jwk_HES_AGF_AzAD_Provider5_cert.crt
+#     cert-thumbprint-sha1 J0OuLdKE1SgPdo4vd-sUXxu2dRs
+#     cert-thumbprint-sha256 Skjhb2v0Y0ARn5RV36Shx6jssXsOEPE2ShAp5wvXzwE
+#     include-x5c yes
+#     key-id J0OuLdKE1SgPdo4vd-sUXxu2dRs
+#     modulus <<redacted>>
+#     public-exponent AQAB
+# }
 # apm oauth jwt-config /HES-SO/auto_jwt_HES_AGF_AzAD_Provider {
 #     allowed-keys {
 #         /HES-SO/auto_jwk_HES_AGF_AzAD_Provider1 { }
 #         /HES-SO/auto_jwk_HES_AGF_AzAD_Provider2 { }
 #         /HES-SO/auto_jwk_HES_AGF_AzAD_Provider3 { }
 #         /HES-SO/auto_jwk_HES_AGF_AzAD_Provider4 { }
+#         /HES-SO/auto_jwk_HES_AGF_AzAD_Provider5 { }
 #     }
 #     allowed-signing-algorithms { RS256 }
 #     auto-generated true
@@ -60925,20 +60936,24 @@
 #     }
 # }
 # sys file ssl-cert /HES-SO/auto_jwk_HES_AGF_AzAD_Provider1_cert.crt {
-#     cache-path /config/filestore/files_d/HES-SO_d/certificate_d/:HES-SO:auto_jwk_HES_AGF_AzAD_Provider1_cert.crt_125280_28
-#     revision 28
+#     cache-path /config/filestore/files_d/HES-SO_d/certificate_d/:HES-SO:auto_jwk_HES_AGF_AzAD_Provider1_cert.crt_125280_29
+#     revision 29
 # }
 # sys file ssl-cert /HES-SO/auto_jwk_HES_AGF_AzAD_Provider2_cert.crt {
-#     cache-path /config/filestore/files_d/HES-SO_d/certificate_d/:HES-SO:auto_jwk_HES_AGF_AzAD_Provider2_cert.crt_125284_28
-#     revision 28
+#     cache-path /config/filestore/files_d/HES-SO_d/certificate_d/:HES-SO:auto_jwk_HES_AGF_AzAD_Provider2_cert.crt_125284_29
+#     revision 29
 # }
 # sys file ssl-cert /HES-SO/auto_jwk_HES_AGF_AzAD_Provider3_cert.crt {
-#     cache-path /config/filestore/files_d/HES-SO_d/certificate_d/:HES-SO:auto_jwk_HES_AGF_AzAD_Provider3_cert.crt_125288_28
-#     revision 28
+#     cache-path /config/filestore/files_d/HES-SO_d/certificate_d/:HES-SO:auto_jwk_HES_AGF_AzAD_Provider3_cert.crt_125288_29
+#     revision 29
 # }
 # sys file ssl-cert /HES-SO/auto_jwk_HES_AGF_AzAD_Provider4_cert.crt {
-#     cache-path /config/filestore/files_d/HES-SO_d/certificate_d/:HES-SO:auto_jwk_HES_AGF_AzAD_Provider4_cert.crt_227975_21
-#     revision 21
+#     cache-path /config/filestore/files_d/HES-SO_d/certificate_d/:HES-SO:auto_jwk_HES_AGF_AzAD_Provider4_cert.crt_227975_22
+#     revision 22
+# }
+# sys file ssl-cert /HES-SO/auto_jwk_HES_AGF_AzAD_Provider5_cert.crt {
+#     cache-path /config/filestore/files_d/HES-SO_d/certificate_d/:HES-SO:auto_jwk_HES_AGF_AzAD_Provider5_cert.crt_241958_1
+#     revision 1
 # }
 # #TMSH-VERSION: 17.1.1.1
 # 

And on the GUI it says I have to apply the policy :

So I believe, base on your fist sentence, that there's a problem :)
Where should I look for it ? Any hint or advice?

Thanks !
Regards,
Olivier B.

Apply should happen automatically. If it's not happening, there is some kind of problem.

The JWK discovery process is implemented as a "rest worker" that operates inside of TMOS's restjavad processes, along with other control-plane stuff. The name of the worker is "OIDCDiscoverTaskCollectionWorker", so you can use a command like this to view its log files:

grep -i discovertask /var/log/restjavad.0.log

The logs will look something like this:

restjavad.0.log:[I][648][10 Apr 2018 00:20:25 UTC][OIDCDiscoverTaskCollectionWorker] Downloading OpenID metadata for provider /Common/my_google_provider task ID 4c2c547f-788e-453c-bdae-8dec7e6ab15e using OpenID URI https://accounts.google.com/.well-known/openid-configuration and Trusted CA Bundle /Common/ca-bundle.crt

For reference, this is a rough outline of the discovery process: