Nginx returns 500 when shibauthorizor returns 302
Closed this issue · 3 comments
aescling commented
Description the bug
Nginx 500s on a protected path with auth request unexpected status: 302 while sending to client when shibauthorizor returns 302 responses.
Expected behaviour
Per the README, 3xx redirects from the authorizor are supposed to be passed back to the client.
Steps to Reproduce Issue
- Attempt to visit a secure path
Setup & Logs
# $ cat /etc/nginx/sites-available/redacted
upstream app_server {
# fail_timeout=0 means we always retry an upstream even if it failed
# to return a good HTTP response
server unix:/tmp/[REDACTED].sock fail_timeout=0;
}
server {
listen 443 http2 ssl;
server_name [REDACTED];
root /var/www/[REDACTED];
ssl_certificate /etc/letsencrypt/live/[REDACTED]/fullchain.pem; # managed by Certbot
ssl_certificate_key /etc/letsencrypt/live/[REDACTED]/privkey.pem; # managed by Certbot
access_log /var/log/nginx/[REDACTED]-access.log;
error_log /var/log/nginx/[REDACTED]-error.log debug;
keepalive_timeout 5;
#FastCGI authorizer for Auth Request module
location = /shibauthorizer {
internal;
include fastcgi_params;
fastcgi_pass unix:/run/shibboleth/shibauthorizer.sock;
}
#FastCGI responder for SSO
location /Shibboleth.sso {
include fastcgi_params;
fastcgi_pass unix:/run/shibboleth/shibresponder.sock;
}
location / {
# checks for static file, if not found proxy to app
try_files $uri @proxy_to_app;
}
location /secure {
auth_request /shibauthorizer;
shib_request_use_headers on;
# Add your attributes here. They get introduced as headers
# by the FastCGI authorizer so we must prevent spoofing.
more_clear_input_headers 'Variable-*' 'Shib-*' 'Remote-User' 'REMOTE_USER' 'Auth-Type' 'AUTH_TYPE' 'unid' 'displayName' 'mail';
# checks for static file, if not found proxy to app
try_files $uri @proxy_to_app;
}
location @proxy_to_app {
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_set_header X-Forwarded-Proto $scheme;
proxy_set_header Host $http_host;
# we don't want nginx trying to do something clever with
# redirects, we set the Host: header above already.
proxy_redirect off;
proxy_pass http://app_server;
}
}<!-- $ cat /etc/shibboleth/shibboleth2.xml -->
<SPConfig xmlns="urn:mace:shibboleth:3.0:native:sp:config"
xmlns:conf="urn:mace:shibboleth:3.0:native:sp:config"
clockSkew="180">
<OutOfProcess tranLogFormat="%u|%s|%IDP|%i|%ac|%t|%attr|%n|%b|%E|%S|%SS|%L|%UA|%a" />
<RequestMapper type="XML">
<RequestMap>
<Host name="[REDACTED]"
authType="shibboleth"
requireSession="true"
redirectToSSL="443">
<PathRegex regex="/secure/.*" />
</Host>
</RequestMap>
</RequestMapper>
<!--
By default, in-memory StorageService, ReplayCache, ArtifactMap, and SessionCache
are used. See example-shibboleth2.xml for samples of explicitly configuring them.
-->
<!-- The ApplicationDefaults element is where most of Shibboleth's SAML bits are defined. -->
<ApplicationDefaults entityID="[REDACTED]"
REMOTE_USER="eppn subject-id pairwise-id persistent-id"
cipherSuites="DEFAULT:!EXP:!LOW:!aNULL:!eNULL:!DES:!IDEA:!SEED:!RC4:!3DES:!kRSA:!SSLv2:!SSLv3:!TLSv1:!TLSv1.1">
<!--
Controls session lifetimes, address checks, cookie handling, and the protocol handlers.
Each Application has an effectively unique handlerURL, which defaults to "/Shibboleth.sso"
and should be a relative path, with the SP computing the full value based on the virtual
host. Use of TLS is now assumed because browsers are enforcing it due to SameSite
restrictions. Note that while we default checkAddress to "false", this makes an assertion
stolen in transit easier for attackers to misuse.
-->
<Sessions lifetime="28800" timeout="3600" relayState="ss:mem"
checkAddress="false" handlerSSL="true" cookieProps="https"
redirectLimit="exact">
<!--
Configures SSO for a default IdP. To properly allow for >1 IdP, remove
entityID property and adjust discoveryURL to point to discovery service.
You can also override entityID on /Login query string, or in RequestMap/htaccess.
-->
<!--
<SSO entityID="urn:mace:incommon:utah.edu"
discoveryProtocol="SAMLDS" discoveryURL="urn:mace:incommon:utah.edu">
SAML2
</SSO>
-->
<SSO
discoveryProtocol="SAMLDS" discoveryURL="[REDACTED]">
SAML2
</SSO>
<!-- SAML and local-only logout. -->
<Logout>SAML2 Local</Logout>
<!-- Administrative logout. -->
<LogoutInitiator type="Admin" Location="/Logout/Admin" acl="127.0.0.1 ::1" />
<!-- Extension service that generates "approximate" metadata based on SP configuration. -->
<Handler type="MetadataGenerator" Location="/Metadata" signing="false"/>
<!-- Status reporting service. -->
<Handler type="Status" Location="/Status" acl="127.0.0.1 ::1"/>
<!-- Session diagnostic service. -->
<Handler type="Session" Location="/Session" showAttributeValues="true"/>
<!-- JSON feed of discovery information. -->
<Handler type="DiscoveryFeed" Location="/DiscoFeed"/>
</Sessions>
<!--
Allows overriding of error template information/filenames. You can
also add your own attributes with values that can be plugged into the
templates, e.g., helpLocation below.
-->
<Errors supportContact="[REDACTED]" />
<!-- Example of remotely supplied batch of signed metadata. -->
<!--
<MetadataProvider type="XML" validate="true"
url="http://federation.org/federation-metadata.xml"
backingFilePath="federation-metadata.xml" maxRefreshDelay="7200">
<MetadataFilter type="RequireValidUntil" maxValidityInterval="2419200"/>
<MetadataFilter type="Signature" certificate="fedsigner.pem" verifyBackup="false"/>
<DiscoveryFilter type="Exclude" matcher="EntityAttributes" trimTags="true"
attributeName="http://macedir.org/entity-category"
attributeNameFormat="urn:oasis:names:tc:SAML:2.0:attrname-format:uri"
attributeValue="http://refeds.org/category/hide-from-discovery" />
</MetadataProvider>
-->
<!-- Example of remotely supplied "on-demand" signed metadata. -->
<!--
<MetadataProvider type="MDQ" validate="true" cacheDirectory="mdq"
baseUrl="http://mdq.federation.org" ignoreTransport="true">
<MetadataFilter type="RequireValidUntil" maxValidityInterval="2419200"/>
<MetadataFilter type="Signature" certificate="mdqsigner.pem" />
</MetadataProvider>
-->
<!-- upstream metadata provider -->
<MetadataProvider type="XML" validate="false" url="[REDACTED]" />
<!-- Map to extract attributes from SAML assertions. -->
<AttributeExtractor type="XML" validate="true" reloadChanges="false" path="attribute-map.xml"/>
<!-- Default filtering policy for recognized attributes, lets other data pass. -->
<AttributeFilter type="XML" validate="true" path="attribute-policy.xml"/>
<!-- Simple file-based resolvers for separate signing/encryption keys. -->
<CredentialResolver type="File" use="signing"
key="sp-signing-key.pem" certificate="sp-signing-cert.pem"/>
<CredentialResolver type="File" use="encryption"
key="sp-encrypt-key.pem" certificate="sp-encrypt-cert.pem"/>
</ApplicationDefaults>
<!-- Policies that determine how to process and authenticate runtime messages. -->
<SecurityPolicyProvider type="XML" validate="true" path="security-policy.xml"/>
<!-- Low-level configuration about protocols and bindings available for use. -->
<ProtocolProvider type="XML" validate="true" reloadChanges="false" path="protocols.xml"/>
</SPConfig>$ cat /var/log/nginx/REDACTED-error.log
2024/11/18 10:25:14 [debug] 639443#639443: *1 event timer del: 54: 425414604
2024/11/18 10:25:14 [debug] 639443#639443: *1 http2 idle handler
2024/11/18 10:25:14 [debug] 639443#639443: *1 http2 send GOAWAY frame: last sid 3, error 0
2024/11/18 10:25:14 [debug] 639443#639443: *1 posix_memalign: 00005DC48F3B3540:512 @16
2024/11/18 10:25:14 [debug] 639443#639443: *1 http2 frame out: 00005DC48F3B3560 sid:0 bl:0 len:8
2024/11/18 10:25:14 [debug] 639443#639443: *1 malloc: 00005DC48FD27A50:16384
2024/11/18 10:25:14 [debug] 639443#639443: *1 SSL buf copy: 17
2024/11/18 10:25:14 [debug] 639443#639443: *1 SSL to write: 17
2024/11/18 10:25:14 [debug] 639443#639443: *1 SSL_write: 17
2024/11/18 10:25:14 [debug] 639443#639443: *1 http2 frame sent: 00005DC48F3B3560 sid:0 bl:0 len:8
2024/11/18 10:25:14 [debug] 639443#639443: *1 SSL_shutdown: 1
2024/11/18 10:25:14 [debug] 639443#639443: *1 reusable connection: 1
2024/11/18 10:25:14 [debug] 639443#639443: *1 event timer add: 54: 5000:425419609
2024/11/18 10:25:14 [debug] 639443#639443: *1 http2 lingering close handler
2024/11/18 10:25:14 [debug] 639443#639443: *1 close http connection: 54
2024/11/18 10:25:14 [debug] 639443#639443: *1 event timer del: 54: 425419609
2024/11/18 10:25:14 [debug] 639443#639443: *1 reusable connection: 0
2024/11/18 10:25:14 [debug] 639443#639443: *1 run cleanup: 00005DC48FA80C80
2024/11/18 10:25:14 [debug] 639443#639443: *1 free: 00005DC48FD27A50
2024/11/18 10:25:14 [debug] 639443#639443: *1 free: 00005DC48FEA6060
2024/11/18 10:25:14 [debug] 639443#639443: *1 free: 00005DC48F3B3330
2024/11/18 10:25:14 [debug] 639443#639443: *1 free: 00005DC48F88E700
2024/11/18 10:25:14 [debug] 639443#639443: *1 free: 00005DC48FA80AC0, unused: 8
2024/11/18 10:25:14 [debug] 639443#639443: *1 free: 00005DC48F3B3750, unused: 8
2024/11/18 10:25:14 [debug] 639443#639443: *1 free: 00005DC48F33BAD0, unused: 16
2024/11/18 10:25:14 [debug] 639443#639443: *1 free: 00005DC48F3B3540, unused: 320
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL ALPN supported by client: h2
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL ALPN supported by client: http/1.1
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL ALPN selected: h2
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL_do_handshake: -1
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL_get_error: 2
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL handshake handler: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 ssl ticket encrypt, key: "467c4864433cbc276dc0cc95cd9cbce8" (new session)
2024/11/18 10:25:17 [debug] 639444#639444: *3 ssl ticket encrypt, key: "467c4864433cbc276dc0cc95cd9cbce8" (new session)
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL_do_handshake: 1
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL: TLSv1.3, cipher: "TLS_AES_256_GCM_SHA384 TLSv1.3 Kx=any Au=any Enc=AESGCM(256) Mac=AEAD"
2024/11/18 10:25:17 [debug] 639444#639444: *3 init http2 connection
2024/11/18 10:25:17 [debug] 639444#639444: *3 malloc: 00005DC48F88E700:480
2024/11/18 10:25:17 [debug] 639444#639444: *3 posix_memalign: 00005DC48EF4FE60:4096 @16
2024/11/18 10:25:17 [debug] 639444#639444: *3 add cleanup: 00005DC48FA80C80
2024/11/18 10:25:17 [debug] 639444#639444: *3 posix_memalign: 00005DC48F3B3750:512 @16
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 send SETTINGS frame
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 send WINDOW_UPDATE frame sid:0, window:2147418112
2024/11/18 10:25:17 [debug] 639444#639444: *3 reusable connection: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 read handler
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL_read: 76
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL_read: 342
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL_read: -1
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL_get_error: 2
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 preface verified
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame type:4 f:0 l:30 sid:0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 SETTINGS frame
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 setting 1:65536
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 setting 2:0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 setting 4:131072
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 setting 5:16384
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 setting 9:1
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame complete pos:00005DC4900076DF end:00005DC490007842
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame type:8 f:0 l:4 sid:0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 WINDOW_UPDATE frame sid:0 window:12517377
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame complete pos:00005DC4900076EC end:00005DC490007842
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame type:1 f:25 l:320 sid:3
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 HEADERS frame sid:3 depends on 0 excl:0 weight:42
2024/11/18 10:25:17 [debug] 639444#639444: *3 posix_memalign: 00005DC48EF3E840:1024 @16
2024/11/18 10:25:17 [debug] 639444#639444: *3 posix_memalign: 00005DC48FEA4040:4096 @16
2024/11/18 10:25:17 [debug] 639444#639444: *3 posix_memalign: 00005DC48FEA5050:4096 @16
2024/11/18 10:25:17 [debug] 639444#639444: *3 event timer del: 54: 425477522
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 get indexed header: 2
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: ":method: GET"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 get indexed name: 5
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:5
2024/11/18 10:25:17 [debug] 639444#639444: *3 http uri: "/secure"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http args: ""
2024/11/18 10:25:17 [debug] 639444#639444: *3 http exten: ""
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: ":path: /secure"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 get indexed name: 1
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:27
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table add: ":authority: [REDACTED]"
2024/11/18 10:25:17 [debug] 639444#639444: *3 malloc: 00005DC48F3B3330:512
2024/11/18 10:25:17 [debug] 639444#639444: *3 malloc: 00005DC48FEA6060:4096
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table account: 80 free:4096
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: ":authority: [RECADTED]"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 get indexed header: 7
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: ":scheme: https"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 get indexed name: 58
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:60
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table add: "user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:132.0) Gecko/20100101 Firefox/132.0"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table account: 122 free:4016
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: "user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:132.0) Gecko/20100101 Firefox/132.0"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 get indexed name: 19
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:48
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table add: "accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table account: 101 free:3894
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: "accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 get indexed name: 17
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:11
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table add: "accept-language: en-US,en;q=0.5"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table account: 61 free:3793
2024/11/18 10:25:17 [debug] 639444#639444: *3 posix_memalign: 00005DC48F33BAD0:512 @16
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: "accept-language: en-US,en;q=0.5"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 get indexed name: 16
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:18
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table add: "accept-encoding: gzip, deflate, br, zstd"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table account: 70 free:3732
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: "accept-encoding: gzip, deflate, br, zstd"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:3
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:1
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table add: "dnt: 1"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table account: 36 free:3662
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: "dnt: 1"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:5
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:1
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table add: "sec-gpc: 1"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table account: 40 free:3626
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: "sec-gpc: 1"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:18
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:1
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table add: "upgrade-insecure-requests: 1"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table account: 58 free:3586
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: "upgrade-insecure-requests: 1"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:10
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:6
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table add: "sec-fetch-dest: document"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table account: 54 free:3528
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: "sec-fetch-dest: document"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:10
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:6
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table add: "sec-fetch-mode: navigate"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table account: 54 free:3474
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: "sec-fetch-mode: navigate"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:10
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:3
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table add: "sec-fetch-site: none"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table account: 50 free:3420
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: "sec-fetch-site: none"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:10
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:2
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table add: "sec-fetch-user: ?1"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table account: 48 free:3370
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: "sec-fetch-user: ?1"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:6
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:5
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table add: "priority: u=0, i"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table account: 46 free:3322
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: "priority: u=0, i"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:2
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 encoded string, len:6
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table add: "te: trailers"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table account: 42 free:3276
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header: "te: trailers"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 request line: "GET /secure HTTP/2.0"
2024/11/18 10:25:17 [debug] 639444#639444: *3 generic phase: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 rewrite phase: 1
2024/11/18 10:25:17 [debug] 639444#639444: *3 test location: "/"
2024/11/18 10:25:17 [debug] 639444#639444: *3 test location: "secure"
2024/11/18 10:25:17 [debug] 639444#639444: *3 using configuration "/secure"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http cl:-1 max:1048576
2024/11/18 10:25:17 [debug] 639444#639444: *3 rewrite phase: 3
2024/11/18 10:25:17 [debug] 639444#639444: *3 headers more rewrite handler, uri "/secure"
2024/11/18 10:25:17 [debug] 639444#639444: *3 rewrite phase: 3
2024/11/18 10:25:17 [debug] 639444#639444: *3 rewrite phase: 4
2024/11/18 10:25:17 [debug] 639444#639444: *3 headers more rewrite handler, uri "/secure"
2024/11/18 10:25:17 [debug] 639444#639444: *3 post rewrite phase: 5
2024/11/18 10:25:17 [debug] 639444#639444: *3 generic phase: 6
2024/11/18 10:25:17 [debug] 639444#639444: *3 generic phase: 7
2024/11/18 10:25:17 [debug] 639444#639444: *3 generic phase: 8
2024/11/18 10:25:17 [debug] 639444#639444: *3 access phase: 9
2024/11/18 10:25:17 [debug] 639444#639444: *3 access phase: 10
2024/11/18 10:25:17 [debug] 639444#639444: *3 access phase: 11
2024/11/18 10:25:17 [debug] 639444#639444: *3 access phase: 12
2024/11/18 10:25:17 [debug] 639444#639444: *3 auth request handler
2024/11/18 10:25:17 [debug] 639444#639444: *3 posix_memalign: 00005DC48FF28250:4096 @16
2024/11/18 10:25:17 [debug] 639444#639444: *3 http subrequest "/shibauthorizer?"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http posted request: "/shibauthorizer?"
2024/11/18 10:25:17 [debug] 639444#639444: *3 rewrite phase: 1
2024/11/18 10:25:17 [debug] 639444#639444: *3 test location: "/"
2024/11/18 10:25:17 [debug] 639444#639444: *3 test location: "secure"
2024/11/18 10:25:17 [debug] 639444#639444: *3 test location: "shibauthorizer"
2024/11/18 10:25:17 [debug] 639444#639444: *3 using configuration "=/shibauthorizer"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http cl:-1 max:1048576
2024/11/18 10:25:17 [debug] 639444#639444: *3 rewrite phase: 3
2024/11/18 10:25:17 [debug] 639444#639444: *3 rewrite phase: 4
2024/11/18 10:25:17 [debug] 639444#639444: *3 headers more rewrite handler, uri "/shibauthorizer"
2024/11/18 10:25:17 [debug] 639444#639444: *3 post rewrite phase: 5
2024/11/18 10:25:17 [debug] 639444#639444: *3 generic phase: 6
2024/11/18 10:25:17 [debug] 639444#639444: *3 generic phase: 7
2024/11/18 10:25:17 [debug] 639444#639444: *3 generic phase: 8
2024/11/18 10:25:17 [debug] 639444#639444: *3 generic phase: 14
2024/11/18 10:25:17 [debug] 639444#639444: *3 generic phase: 15
2024/11/18 10:25:17 [debug] 639444#639444: *3 http init upstream, client timer: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 post event 00005DC48EF501B8
2024/11/18 10:25:17 [debug] 639444#639444: *3 posix_memalign: 00005DC48FF29260:4096 @16
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "QUERY_STRING"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "QUERY_STRING: "
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "REQUEST_METHOD"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script var: "GET"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "REQUEST_METHOD: GET"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "CONTENT_TYPE"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "CONTENT_TYPE: "
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "CONTENT_LENGTH"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "CONTENT_LENGTH: "
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "SCRIPT_NAME"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script var: "/shibauthorizer"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "SCRIPT_NAME: /shibauthorizer"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "REQUEST_URI"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script var: "/secure"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "REQUEST_URI: /secure"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "DOCUMENT_URI"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script var: "/shibauthorizer"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "DOCUMENT_URI: /shibauthorizer"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "DOCUMENT_ROOT"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script var: "/var/www/[REDACTED]"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "DOCUMENT_ROOT: /var/www/[REDACTED]"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "SERVER_PROTOCOL"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script var: "HTTP/2.0"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "SERVER_PROTOCOL: HTTP/2.0"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "REQUEST_SCHEME"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script var: "https"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "REQUEST_SCHEME: https"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "HTTPS"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script var: "on"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "HTTPS: on"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "GATEWAY_INTERFACE"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "CGI/1.1"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "GATEWAY_INTERFACE: CGI/1.1"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "SERVER_SOFTWARE"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "nginx/"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script var: "1.24.0"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "SERVER_SOFTWARE: nginx/1.24.0"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "REMOTE_ADDR"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script var: "10.128.2.81"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "REMOTE_ADDR: 10.128.2.81"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "REMOTE_PORT"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script var: "52311"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "REMOTE_PORT: 52311"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "REMOTE_USER"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "REMOTE_USER: "
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "SERVER_ADDR"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script var: "128.110.106.133"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "SERVER_ADDR: 128.110.106.133"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "SERVER_PORT"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script var: "443"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "SERVER_PORT: 443"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "SERVER_NAME"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script var: "[REDACTED]"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "SERVER_NAME: [REDACTED]"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "REDIRECT_STATUS"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http script copy: "200"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "REDIRECT_STATUS: 200"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "HTTP_HOST: [REDACTED]"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "HTTP_USER_AGENT: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:132.0) Gecko/20100101 Firefox/132.0"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "HTTP_ACCEPT: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "HTTP_ACCEPT_LANGUAGE: en-US,en;q=0.5"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "HTTP_ACCEPT_ENCODING: gzip, deflate, br, zstd"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "HTTP_DNT: 1"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "HTTP_SEC_GPC: 1"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "HTTP_UPGRADE_INSECURE_REQUESTS: 1"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "HTTP_SEC_FETCH_DEST: document"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "HTTP_SEC_FETCH_MODE: navigate"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "HTTP_SEC_FETCH_SITE: none"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "HTTP_SEC_FETCH_USER: ?1"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "HTTP_PRIORITY: u=0, i"
2024/11/18 10:25:17 [debug] 639444#639444: *3 fastcgi param: "HTTP_TE: trailers"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http cleanup add: 00005DC48FF28F28
2024/11/18 10:25:17 [debug] 639444#639444: *3 get rr peer, try: 1
2024/11/18 10:25:17 [debug] 639444#639444: *3 stream socket 55
2024/11/18 10:25:17 [debug] 639444#639444: *3 epoll add connection: fd:55 ev:80002005
2024/11/18 10:25:17 [debug] 639444#639444: *3 connect to unix:/run/shibboleth/shibauthorizer.sock, fd:55 #4
2024/11/18 10:25:17 [debug] 639444#639444: *3 connected
2024/11/18 10:25:17 [debug] 639444#639444: *3 http upstream connect: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 posix_memalign: 00005DC48FA6E2D0:128 @16
2024/11/18 10:25:17 [debug] 639444#639444: *3 http upstream send request
2024/11/18 10:25:17 [debug] 639444#639444: *3 http upstream send request body
2024/11/18 10:25:17 [debug] 639444#639444: *3 chain writer buf fl:0 s:1032
2024/11/18 10:25:17 [debug] 639444#639444: *3 chain writer in: 00005DC48FF28F68
2024/11/18 10:25:17 [debug] 639444#639444: *3 writev: 1032 of 1032
2024/11/18 10:25:17 [debug] 639444#639444: *3 chain writer out: 0000000000000000
2024/11/18 10:25:17 [debug] 639444#639444: *3 event timer add: 55: 60000:425477618
2024/11/18 10:25:17 [debug] 639444#639444: *3 http finalize request: -4, "/shibauthorizer?" a:1, c:3
2024/11/18 10:25:17 [debug] 639444#639444: *3 http request count:3 blk:0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame complete pos:00005DC490007835 end:00005DC490007842
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame type:8 f:0 l:4 sid:3
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 WINDOW_UPDATE frame sid:3 window:12451840
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame complete pos:00005DC490007842 end:00005DC490007842
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame out: 00005DC48EF50018 sid:0 bl:0 len:0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame out: 00005DC48EF4FF68 sid:0 bl:0 len:4
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame out: 00005DC48EF4FEB0 sid:0 bl:0 len:18
2024/11/18 10:25:17 [debug] 639444#639444: *3 malloc: 00005DC48FD27A50:16384
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL buf copy: 27
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL buf copy: 13
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL buf copy: 9
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL to write: 49
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL_write: 49
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame sent: 00005DC48EF4FEB0 sid:0 bl:0 len:18
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame sent: 00005DC48EF4FF68 sid:0 bl:0 len:4
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame sent: 00005DC48EF50018 sid:0 bl:0 len:0
2024/11/18 10:25:17 [debug] 639444#639444: *3 delete posted event 00005DC48EF501B8
2024/11/18 10:25:17 [debug] 639444#639444: *3 http run request: "/shibauthorizer?"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http upstream check client, write event:0, "/shibauthorizer"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http upstream request: "/shibauthorizer?"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http upstream dummy handler
2024/11/18 10:25:17 [debug] 639444#639444: *3 http upstream request: "/shibauthorizer?"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http upstream process header
2024/11/18 10:25:17 [debug] 639444#639444: *3 malloc: 00005DC48FF2A270:4096
2024/11/18 10:25:17 [debug] 639444#639444: *3 recv: eof:1, avail:-1
2024/11/18 10:25:17 [debug] 639444#639444: *3 recv: fd:55 544 of 4096
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi record byte: 01
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi record byte: 06
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi record byte: 00
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi record byte: 01
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi record byte: 01
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi record byte: FE
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi record byte: 02
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi record byte: 00
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi record length: 510
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi parser: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi header: "Status: 302 Please Wait"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi parser: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi header: "Location: https://incommon2.sso.utah.edu/idp/profile/SAML2/POST/SSO?entityID=[REDACTED]&return=https%3A%2F%[REDACTED]%2FShibboleth.sso%2FLogin%3FSAMLDS%3D1%26target%3Dss%253Amem%253Ad2090d976c60c56a4127b56d8b94def479bc2cdb6b1da37e6ba41bdf87017aed"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi parser: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi header: "Content-Type: text/html"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi parser: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi header: "Content-Length: 40"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi parser: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi header: "Expires: Wed, 01 Jan 1997 12:00:00 GMT"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi parser: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi header: "Cache-Control: private,no-store,no-cache,max-age=0"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi parser: 1
2024/11/18 10:25:17 [debug] 639444#639444: *3 http fastcgi header done
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header filter
2024/11/18 10:25:17 [debug] 639444#639444: *3 finalize http upstream request: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 finalize http fastcgi request
2024/11/18 10:25:17 [debug] 639444#639444: *3 free rr peer 1 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 close http upstream connection: 55
2024/11/18 10:25:17 [debug] 639444#639444: *3 free: 00005DC48FA6E2D0, unused: 48
2024/11/18 10:25:17 [debug] 639444#639444: *3 event timer del: 55: 425477618
2024/11/18 10:25:17 [debug] 639444#639444: *3 reusable connection: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http finalize request: 0, "/shibauthorizer?" a:1, c:2
2024/11/18 10:25:17 [debug] 639444#639444: *3 auth request done s:302
2024/11/18 10:25:17 [debug] 639444#639444: *3 http wake parent request: "/secure?"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http posted request: "/secure?"
2024/11/18 10:25:17 [debug] 639444#639444: *3 access phase: 12
2024/11/18 10:25:17 [debug] 639444#639444: *3 auth request handler
2024/11/18 10:25:17 [debug] 639444#639444: *3 auth request set variables
2024/11/18 10:25:17 [error] 639444#639444: *3 auth request unexpected status: 302 while sending to client, client: 10.128.2.81, server: [REDACTED], request: "GET /secure HTTP/2.0", host: "[REDACTED]"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http finalize request: 500, "/secure?" a:1, c:1
2024/11/18 10:25:17 [debug] 639444#639444: *3 http special response: 500, "/secure?"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 header filter
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 table size update: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 output header: ":status: 500"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 output header: "server: nginx"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 output header: "date: Mon, 18 Nov 2024 17:25:17 GMT"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 output header: "content-type: text/html"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 output header: "content-length: 170"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2:3 create HEADERS frame 00005DC48FF298A8: len:46 fin:0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http cleanup add: 00005DC48FF299A0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame out: 00005DC48FF298A8 sid:3 bl:1 len:46
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL buf copy: 9
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL buf copy: 46
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2:3 HEADERS frame 00005DC48FF298A8 was sent
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame sent: 00005DC48FF298A8 sid:3 bl:1 len:46
2024/11/18 10:25:17 [debug] 639444#639444: *3 http output filter "/secure?"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http copy filter: "/secure?"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http postpone filter "/secure?" 00005DC48FF29AD8
2024/11/18 10:25:17 [debug] 639444#639444: *3 write new buf t:0 f:0 0000000000000000, pos 00005DC48E0ECAA0, size: 124 file: 0, size: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 write new buf t:0 f:0 0000000000000000, pos 00005DC48E0EDB60, size: 46 file: 0, size: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http write filter: l:1 f:0 s:170
2024/11/18 10:25:17 [debug] 639444#639444: *3 http write filter limit 2097152
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 send chain: 00005DC48FF29AF8
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2:3 windows: conn:12582912 stream:12582912
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2:3 create DATA frame 00005DC48FF298A8: len:170 flags:1
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame out: 00005DC48FF298A8 sid:3 bl:0 len:170
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL buf copy: 9
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL buf copy: 124
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL buf copy: 46
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL to write: 234
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL_write: 234
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2:3 DATA frame 00005DC48FF298A8 was sent
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame sent: 00005DC48FF298A8 sid:3 bl:0 len:170
2024/11/18 10:25:17 [debug] 639444#639444: *3 http write filter 0000000000000000
2024/11/18 10:25:17 [debug] 639444#639444: *3 http copy filter: 0 "/secure?"
2024/11/18 10:25:17 [debug] 639444#639444: *3 http finalize request: 0, "/secure?" a:1, c:1
2024/11/18 10:25:17 [debug] 639444#639444: *3 http request count:1 blk:0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 close stream 3, queued 0, processing 1, pushing 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http close request
2024/11/18 10:25:17 [debug] 639444#639444: *3 http log handler
2024/11/18 10:25:17 [debug] 639444#639444: *3 free: 00005DC48FF2A270
2024/11/18 10:25:17 [debug] 639444#639444: *3 free: 00005DC48FEA4040, unused: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 free: 00005DC48FEA5050, unused: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 free: 00005DC48FF28250, unused: 11
2024/11/18 10:25:17 [debug] 639444#639444: *3 free: 00005DC48FF29260, unused: 1635
2024/11/18 10:25:17 [debug] 639444#639444: *3 free: 00005DC48EF3E840, unused: 491
2024/11/18 10:25:17 [debug] 639444#639444: *3 post event 00005DC48FFE37A0
2024/11/18 10:25:17 [debug] 639444#639444: *3 delete posted event 00005DC48FFE37A0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 handle connection handler
2024/11/18 10:25:17 [debug] 639444#639444: *3 event timer add: 54: 5000:425422623
2024/11/18 10:25:17 [debug] 639444#639444: *3 reusable connection: 1
2024/11/18 10:25:17 [debug] 639444#639444: *3 free: 00005DC48EF4FE60, unused: 2944
2024/11/18 10:25:17 [debug] 639444#639444: *3 free: 00005DC48FD27A50
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 idle handler
2024/11/18 10:25:17 [debug] 639444#639444: *3 reusable connection: 0
2024/11/18 10:25:17 [debug] 639444#639444: *3 posix_memalign: 00005DC48EF4FE60:4096 @16
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 read handler
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL_read: 9
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL_read: -1
2024/11/18 10:25:17 [debug] 639444#639444: *3 SSL_get_error: 2
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame type:4 f:1 l:0 sid:0
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 SETTINGS frame
2024/11/18 10:25:17 [debug] 639444#639444: *3 http2 frame complete pos:00005DC4900076A9 end:00005DC4900076A9
2024/11/18 10:25:17 [debug] 639444#639444: *3 reusable connection: 1
2024/11/18 10:25:17 [debug] 639444#639444: *3 free: 00005DC48EF4FE60, unused: 4016
2024/11/18 10:25:22 [debug] 639444#639444: *3 event timer del: 54: 425422623
2024/11/18 10:25:22 [debug] 639444#639444: *3 http2 idle handler
2024/11/18 10:25:22 [debug] 639444#639444: *3 http2 send GOAWAY frame: last sid 3, error 0
2024/11/18 10:25:22 [debug] 639444#639444: *3 posix_memalign: 00005DC48F3B3540:512 @16
2024/11/18 10:25:22 [debug] 639444#639444: *3 http2 frame out: 00005DC48F3B3560 sid:0 bl:0 len:8
2024/11/18 10:25:22 [debug] 639444#639444: *3 malloc: 00005DC48FD27A50:16384
2024/11/18 10:25:22 [debug] 639444#639444: *3 SSL buf copy: 17
2024/11/18 10:25:22 [debug] 639444#639444: *3 SSL to write: 17
2024/11/18 10:25:22 [debug] 639444#639444: *3 SSL_write: 17
2024/11/18 10:25:22 [debug] 639444#639444: *3 http2 frame sent: 00005DC48F3B3560 sid:0 bl:0 len:8
2024/11/18 10:25:22 [debug] 639444#639444: *3 SSL_shutdown: 1
2024/11/18 10:25:22 [debug] 639444#639444: *3 reusable connection: 1
2024/11/18 10:25:22 [debug] 639444#639444: *3 event timer add: 54: 5000:425427628
2024/11/18 10:25:22 [debug] 639444#639444: *3 http2 lingering close handler
2024/11/18 10:25:22 [debug] 639444#639444: *3 close http connection: 54
2024/11/18 10:25:22 [debug] 639444#639444: *3 event timer del: 54: 425427628
2024/11/18 10:25:22 [debug] 639444#639444: *3 reusable connection: 0
2024/11/18 10:25:22 [debug] 639444#639444: *3 run cleanup: 00005DC48FA80C80
2024/11/18 10:25:22 [debug] 639444#639444: *3 free: 00005DC48FD27A50
2024/11/18 10:25:22 [debug] 639444#639444: *3 free: 00005DC48FEA6060
2024/11/18 10:25:22 [debug] 639444#639444: *3 free: 00005DC48F3B3330
2024/11/18 10:25:22 [debug] 639444#639444: *3 free: 00005DC48F88E700
2024/11/18 10:25:22 [debug] 639444#639444: *3 free: 00005DC48FA80AC0, unused: 8
2024/11/18 10:25:22 [debug] 639444#639444: *3 free: 00005DC48F3B3750, unused: 8
2024/11/18 10:25:22 [debug] 639444#639444: *3 free: 00005DC48F33BAD0, unused: 16
2024/11/18 10:25:22 [debug] 639444#639444: *3 free: 00005DC48F3B3540, unused: 320
Versions and Systems
(nginx -V, shibd -v (and compile options), OS type and version)
We are using Ubuntu 24.04.
$ nginx -V
nginx version: nginx/1.24.0 (Ubuntu)
built with OpenSSL 3.0.13 30 Jan 2024
TLS SNI support enabled
configure arguments: --with-cc-opt='-g -O2 -fno-omit-frame-pointer -mno-omit-leaf-frame-pointer -ffile-prefix-map=/build/nginx-DlMnQR/nginx-1.24.0=. -flto=auto -ffat-lto-objects -fstack-protector-strong -fstack-clash-protection -Wformat -Werror=format-security -fcf-protection -fdebug-prefix-map=/build/nginx-DlMnQR/nginx-1.24.0=/usr/src/nginx-1.24.0-2ubuntu7.1 -fPIC -Wdate-time -D_FORTIFY_SOURCE=3' --with-ld-opt='-Wl,-Bsymbolic-functions -flto=auto -ffat-lto-objects -Wl,-z,relro -Wl,-z,now -fPIC' --prefix=/usr/share/nginx --conf-path=/etc/nginx/nginx.conf --http-log-path=/var/log/nginx/access.log --error-log-path=stderr --lock-path=/var/lock/nginx.lock --pid-path=/run/nginx.pid --modules-path=/usr/lib/nginx/modules --http-client-body-temp-path=/var/lib/nginx/body --http-fastcgi-temp-path=/var/lib/nginx/fastcgi --http-proxy-temp-path=/var/lib/nginx/proxy --http-scgi-temp-path=/var/lib/nginx/scgi --http-uwsgi-temp-path=/var/lib/nginx/uwsgi --with-compat --with-debug --with-pcre-jit --with-http_ssl_module --with-http_stub_status_module --with-http_realip_module --with-http_auth_request_module --with-http_v2_module --with-http_dav_module --with-http_slice_module --with-threads --with-http_addition_module --with-http_flv_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_mp4_module --with-http_random_index_module --with-http_secure_link_module --with-http_sub_module --with-mail_ssl_module --with-stream_ssl_module --with-stream_ssl_preread_module --with-stream_realip_module --with-http_geoip_module=dynamic --with-http_image_filter_module=dynamic --with-http_perl_module=dynamic --with-http_xslt_module=dynamic --with-mail=dynamic --with-stream=dynamic --with-stream_geoip_module=dynamic
$ shibd -v
shibboleth 3.4.1
Additional context
Add any other context about the problem here.
davidjb commented
You'll need to use shib_request instead of auth_request to activate this module's handling:
location /secure {
auth_request /shibauthorizer;
shib_request_use_headers on;needs to be
location /secure {
shib_request /shibauthorizer;
shib_request_use_headers on;Once this is enabled, you'll start seeing shib request ... debug messages in your logs instead of the auth request ... messages currently being logged via auth_request, which is where the 500 response is coming from.
The rest of the config looks fine at a glance. If try_files happens to cause you issues sending headers to the backend, try moving proxy_pass your application config into the /secure block directly and see if that works - Nginx has interesting ways of handling subrequests and this may affect what reaches your app.
aescling commented
Thank you so much for your time, this resolved the issue. I feel very silly for missing that.
davidjb commented
No worries at all - really glad it’s working and the fix was a simple one 🙂. Thanks for the detailed debugging logs and config, that was really helpful.