ondemand icon indicating copy to clipboard operation
ondemand copied to clipboard
verified publisher icon OSC

mod_auth_openidc: newer versions cause lots of warnings about OIDCXForwardedHeaders

Open CSC-swesters opened this issue 1 year ago • 6 comments

We upgraded mod_auth_openidc to a newer version (we have tested 2.4.15.7 and 2.4.16.4 specifically), in order to get certain site-specific functionality working. We noticed that there is a noticeable amount of warning logs from the module, which complain about mismatches in expectations of X-Forwarded-* headers. See the configuration documentation here for details.

The default value of OIDCXForwardedHeaders none causes warnings each time one of the headers appears, and if one were to set it to X-Forwarded-Proto for example, it would warn whenever the header is missing.

The X-Forwarded-Proto header is the only one we've observed in our OOD deployments, and the total amount of logging is roughly 35% of the OOD instance's log line count, when using the default OIDCXForwardedHeaders none configuration. So it's a significant issue.

The mod_auth_openidc project seems to not offer any way of avoiding this check, or warning log, which indicates to me that sites should have this working correctly.

My questions for OOD are:

  1. Why are we seeing X-Forwarded-Proto warnings from making a request to the dashboard?

I noticed that the header is set in the Lua proxy code, and this is what triggers the warnings from mod_auth_openidc. Commenting out this line in proxy.lua removes the warning logs altogether.

  1. What is this header used for downstream?
  2. Could it simply be removed?
  3. If not, could it be injected in some other way, which would not irritate mod_auth_openidc?

Some additional info:

  • While debugging httpd behavior, it seems like mod_auth_openidc checks the headers multiple times per end-user HTTP request (e.g. GET /pun/sys/dashboard). I saw three checks per request in our deployment. It seems that mod_auth_openidc is hooked into multiple stages of request processing.
  • We experimented with always removing the X-Forwarded-Proto header using RequestHeader unset X-Forwarded-Proto early. This didn't work completely, since the proxy.lua addition still happened by the end of request handling, and mod_auth_openidc ran its check once after that as well...
    • Note the early request processing is not recommended for production setups: https://httpd.apache.org/docs/current/mod/mod_headers.html#early

Thanks in advance!

CSC-swesters avatar Oct 17 '24 10:10 CSC-swesters

  1. Why are we seeing X-Forwarded-Proto warnings from making a request to the dashboard?
  1. What is this header used for downstream?

Unfortunately the commit that adds it doesn't give us much information. Ostensibly, it's so the origin server can make some sort of toggle. While the dashboard may not care, it's sort of a larger issue when we talk about what other Passenger apps could be out there in the wild, and how they may be reacting to this.

https://github.com/OSC/ondemand/commit/c7ab1c71af4aa606e491424a8ef83eb200bc6dbd

  1. Could it simply be removed?

Maybe. But again, it brings into question comparability with Passenger apps in the wild. Someone may be using it, though I can't say for sure.

Why not just configure OIDCXForwardedHeaders to allow the X-Forwarded-Proto header?

johrstrom avatar Oct 17 '24 13:10 johrstrom

While the dashboard may not care, it's sort of a larger issue when we talk about what other Passenger apps could be out there in the wild, and how they may be reacting to this.

Based on my understanding this is the risk with disabling it, yes. Downstream apps might behave differently if they do not know whether the connection is secure or not. I suppose we would need to test this and make a decision based on the outcomes. But good to know that OOD's default apps don't rely on it.

Why not just configure OIDCXForwardedHeaders to allow the X-Forwarded-Proto header?

Good question, sorry for not bringing that up earlier. I already tested this as well, and it also causes a non-zero amount of warnings due to the logic I described above:

if one were to set it to X-Forwarded-Proto for example, it would warn whenever the header is missing.

A quick 1-minute test with this option on yields 89 warning lines in a total of 256 httpd log lines. So this is not really a viable option either.

$ ts="2024-10-21T14:43:00" ; \
>    gawk "{if (\$1 > $(date +%s --date=${ts:?})) print }" < log | grep -cE ' ondemand_httpd ' ;  \
>    gawk "{if (\$1 > $(date +%s --date=${ts:?})) print }" < log | grep -cE 'oidc_check_x_forwarded_hdr' ;
256 # Total httpd log lines
89  # OIDC warning lines

I believe that the mod_auth_openidc that OOD bundles doesn't yet have these warnings, but if you plan on upgrading that to something newer, other sites will run into this as well. The parsing of these headers seems to have been introduced in version 2.4.11rc0 (commit).

It would be nice to understand what the correct way of handling this might be, and how to avoid the warning logs, so please let us know if you have ideas here.

CSC-swesters avatar Oct 21 '24 12:10 CSC-swesters

I've encountered this issue as well, and the approach that I took was to allow the headers. As you say, when a header is missing, then the logs will warn about that as well, but I haven't seen new warnings about missing headers. I'm working in a development environment, so it's possible that will come later.

I also ran into an issue where when I enabled the missing headers, the port was included in the request url, causing OIDC authentication through dex to fail. I addressed this by allowing the url with the port as an OIDC redirect URI. The better config for me looks like

oidc_settings:
  OIDCXForwardedHeaders: X-Forwarded-Proto X-Forwarded-Port
dex_uri: /dex
dex:
  client_redirect_uris:
    - 'https://${WEBSITE_DOMAIN}:443/oidc'
# rest of the dex config unchanged

That has WEBSITE_DOMAIN subbed in for the domain of the environment being deployed.

jaguillette avatar May 22 '25 13:05 jaguillette

3. Could it simply be removed?

Maybe. But again, it brings into question comparability with Passenger apps in the wild. Someone may be using it, though I can't say for sure.

I tried this today, and can report that some Rails middleware will be unhappy about the X-Forwarded-Proto header being missing when submitting a Slurm job. I got an HTTP 422 error ("Unprocessable Content") and the following Passenger logs:

App 4729 output: [2025-06-24 10:13:51 +0300 ]  WARN "HTTP Origin header (https://my-redacted-hostname) didn't match request.base_url (http://my-redacted-hostname)"
App 4729 output: [2025-06-24 10:13:51 +0300 ]  INFO "method=POST path=/pun/sys/dashboard/batch_connect/sys/ood-vnc/session_contexts format=html controller=BatchConnect::SessionContextsController action=create status=422 allocations=216 duration=0.49 view=0.00"
App 4729 output: [2025-06-24 10:13:51 +0300 ] FATAL "ActionController::InvalidAuthenticityToken (HTTP Origin header (https://my-redacted-hostname) didn't match request.base_url (http://my-redacted-hostname)):
  
actionpack (7.0.8.5) lib/action_controller/metal/request_forgery_protection.rb:253:in `handle_unverified_request'
actionpack (7.0.8.5) lib/action_controller/metal/request_forgery_protection.rb:286:in `handle_unverified_request'
actionpack (7.0.8.5) lib/action_controller/metal/request_forgery_protection.rb:275:in `verify_authenticity_token'
activesupport (7.0.8.5) lib/active_support/callbacks.rb:400:in `block in make_lambda'
activesupport (7.0.8.5) lib/active_support/callbacks.rb:199:in `block (2 levels) in halting'
actionpack (7.0.8.5) lib/abstract_controller/callbacks.rb:34:in `block (2 levels) in <module:Callbacks>'
activesupport (7.0.8.5) lib/active_support/callbacks.rb:200:in `block in halting'
activesupport (7.0.8.5) lib/active_support/callbacks.rb:595:in `block in invoke_before'
activesupport (7.0.8.5) lib/active_support/callbacks.rb:595:in `each'
activesupport (7.0.8.5) lib/active_support/callbacks.rb:595:in `invoke_before'
activesupport (7.0.8.5) lib/active_support/callbacks.rb:116:in `block in run_callbacks'
turbo-rails (2.0.7) lib/turbo-rails.rb:24:in `with_request_id'
turbo-rails (2.0.7) app/controllers/concerns/turbo/request_id_tracking.rb:10:in `turbo_tracking_request_id'
activesupport (7.0.8.5) lib/active_support/callbacks.rb:127:in `block in run_callbacks'
activesupport (7.0.8.5) lib/active_support/callbacks.rb:138:in `run_callbacks'
actionpack (7.0.8.5) lib/abstract_controller/callbacks.rb:233:in `process_action'
actionpack (7.0.8.5) lib/action_controller/metal/rescue.rb:23:in `process_action'
actionpack (7.0.8.5) lib/action_controller/metal/instrumentation.rb:67:in `block in process_action'
activesupport (7.0.8.5) lib/active_support/notifications.rb:206:in `block in instrument'
activesupport (7.0.8.5) lib/active_support/notifications/instrumenter.rb:24:in `instrument'
activesupport (7.0.8.5) lib/active_support/notifications.rb:206:in `instrument'
actionpack (7.0.8.5) lib/action_controller/metal/instrumentation.rb:66:in `process_action'
actionpack (7.0.8.5) lib/action_controller/metal/params_wrapper.rb:259:in `process_action'
actionpack (7.0.8.5) lib/abstract_controller/base.rb:151:in `process'
actionview (7.0.8.5) lib/action_view/rendering.rb:39:in `process'
actionpack (7.0.8.5) lib/action_controller/metal.rb:188:in `dispatch'
actionpack (7.0.8.5) lib/action_controller/metal.rb:251:in `dispatch'
actionpack (7.0.8.5) lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
actionpack (7.0.8.5) lib/action_dispatch/routing/route_set.rb:32:in `serve'
actionpack (7.0.8.5) lib/action_dispatch/journey/router.rb:50:in `block in serve'
actionpack (7.0.8.5) lib/action_dispatch/journey/router.rb:32:in `each'
actionpack (7.0.8.5) lib/action_dispatch/journey/router.rb:32:in `serve'
actionpack (7.0.8.5) lib/action_dispatch/routing/route_set.rb:852:in `call'
rack (2.2.10) lib/rack/tempfile_reaper.rb:15:in `call'
rack (2.2.10) lib/rack/etag.rb:27:in `call'
rack (2.2.10) lib/rack/conditional_get.rb:40:in `call'
rack (2.2.10) lib/rack/head.rb:12:in `call'
actionpack (7.0.8.5) lib/action_dispatch/http/permissions_policy.rb:38:in `call'
actionpack (7.0.8.5) lib/action_dispatch/http/content_security_policy.rb:36:in `call'
rack (2.2.10) lib/rack/session/abstract/id.rb:266:in `context'
rack (2.2.10) lib/rack/session/abstract/id.rb:260:in `call'
actionpack (7.0.8.5) lib/action_dispatch/middleware/cookies.rb:704:in `call'
actionpack (7.0.8.5) lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
activesupport (7.0.8.5) lib/active_support/callbacks.rb:99:in `run_callbacks'
actionpack (7.0.8.5) lib/action_dispatch/middleware/callbacks.rb:26:in `call'
actionpack (7.0.8.5) lib/action_dispatch/middleware/debug_exceptions.rb:28:in `call'
actionpack (7.0.8.5) lib/action_dispatch/middleware/show_exceptions.rb:29:in `call'
lograge (0.14.0) lib/lograge/rails_ext/rack/logger.rb:18:in `call_app'
railties (7.0.8.5) lib/rails/rack/logger.rb:25:in `block in call'
activesupport (7.0.8.5) lib/active_support/tagged_logging.rb:99:in `block in tagged'
activesupport (7.0.8.5) lib/active_support/tagged_logging.rb:37:in `tagged'
activesupport (7.0.8.5) lib/active_support/tagged_logging.rb:99:in `tagged'
railties (7.0.8.5) lib/rails/rack/logger.rb:25:in `call'
actionpack (7.0.8.5) lib/action_dispatch/middleware/remote_ip.rb:93:in `call'
request_store (1.7.0) lib/request_store/middleware.rb:19:in `call'
actionpack (7.0.8.5) lib/action_dispatch/middleware/request_id.rb:26:in `call'
rack (2.2.10) lib/rack/method_override.rb:24:in `call'
rack (2.2.10) lib/rack/runtime.rb:22:in `call'
actionpack (7.0.8.5) lib/action_dispatch/middleware/executor.rb:14:in `call'
rack (2.2.10) lib/rack/sendfile.rb:110:in `call'
actionpack (7.0.8.5) lib/action_dispatch/middleware/host_authorization.rb:138:in `call'
railties (7.0.8.5) lib/rails/engine.rb:530:in `call'
/opt/rh/ondemand/root/usr/share/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:107:in `process_request'
/opt/rh/ondemand/root/usr/share/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:157:in `accept_and_process_next_request'
/opt/rh/ondemand/root/usr/share/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:110:in `main_loop'
/opt/rh/ondemand/root/usr/share/ruby/vendor_ruby/phusion_passenger/request_handler.rb:419:in `block (3 levels) in start_threads'
/opt/rh/ondemand/root/usr/share/ruby/vendor_ruby/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'"

I tried various combinations of expecting OIDCXForwardedHeaders and setting or unsetting the X-Forwarded-Proto header in the ood-portal.conf (early vs. late, set vs. unset), but none of the combinations actually removed the warnings in httpd's logs when hard-refreshing the dashboard app. I get warnings both when expecting and not expecting the headers:

# Expected, i.e., "OIDCXForwardedHeaders X-Forwarded-Proto"
oidc_check_x_forwarded_hdr: OIDCXForwardedHeaders configured for header X-Forwarded-Proto but not found in request, referer: https://my-redacted-hostname/pun/sys/dashboard/

# Not expected, i.e.  "OIDCXForwardedHeaders none" (the default config):
oidc_check_x_forwarded_hdr: header X-Forwarded-Proto received but OIDCXForwardedHeaders not configured for it, referer: https://my-redacted-hostname/pun/sys/dashboard/

To be clear, the httpd server is at the edge of the network, so no reverse proxies are in front of it and mod_auth_openidc. We're currently testing mod_auth_openidc 2.4.17.

I'm starting to think that the easiest way out would be to filter out these log messages in other parts of the stack... Let me know if you have other ideas.

CSC-swesters avatar Jun 24 '25 09:06 CSC-swesters

Hi again,

I reached out to the mod_auth_openidc project and asked if the logs could be ignored, and they very quickly added a possibility to do that! See https://github.com/OpenIDC/mod_auth_openidc/discussions/1333#discussioncomment-13572107

So there's a patch now if anybody wants to pick it up. Otherwise, I suppose the new environment variable will be available in version 2.4.17.2 whenever it is released.

Regarding OOD's role in this issue, it could still be considered whether the httpd configuration should be put into the ood-portal.conf.erb template, for ease of use. Any opinions on this?

Basically something like this would be needed to disable the logging (see the discussion linked above):

  SetEnvIfExpr true OIDC_CHECK_X_FORWARDED_HDR_LOG_DISABLE=X-Forwarded-Proto

CSC-swesters avatar Jun 25 '25 13:06 CSC-swesters

GitHub review meeting notes: Explained that newer versions of ModAuth OpenIDC generate many warnings User had provided a workaround in the issue Noted that user's company manages more users and notices issues at scale

Conclusion: Scheduled tentatively for version 4.1 Team will implement user's workaround

moffatsadeghi avatar Sep 22 '25 16:09 moffatsadeghi