search

nginx-shib / nginx-http-shibboleth

Shibboleth auth request module for nginx
https://github.com/nginx-shib/nginx-http-shibboleth/wiki
Other
209 stars 27 forks source link

Shibboleth attributes are not being proxy_passed in headers (NGINX) #41

Closed asonj closed 3 years ago

asonj commented 3 years ago

Description of the Issue

I am using Shibboleth SSO for user authentication on a website, NodeJS backend with a NGINX proxy. I am able to login through the IdP and it redirects back to the callback URL. The problem is I cannot create an account on the NodeJS side because the shibboleth session variables are not being passed through the headers. I know Shibboleth SP is working because I can go to https://domain.com/Shibboleth.sso/Session and see the attributes listed. I used this guide 1 and this guide 2 as a reference when setting everything up.

I have read and tried seemingly everything. I've been stuck on this issue for days and am at my wits end.

Expected behaviour

I expect using shib_request_use_headers on; shib_request /shibauthorizer; to copy Shibboleth attributes onto the request headers. However, no shibboleth attributes are available on the nodejs side, I believe this could be due to them being blank strings, in which case why arent they being set? I even tried manually setting proxy_set_header shib_mail $upstream_http_variable_mail and it does not come through.

Related Issues

Seems related to NGINX not passing Shibboleth session variables in header #9 where RequestMapper was the issue. I have tried many different variants of my RequestMapper with no luck.

Shibboleth Session (/Shibboleth.sso/Session)

Miscellaneous
Session Expiration (barring inactivity): 468 minute(s)
Client Address: redacted
SSO Protocol: urn:oasis:names:tc:SAML:2.0:protocol
Identity Provider: redacted
Authentication Time: 2020-12-11T22:44:22.342Z
Authentication Context Class: urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport
Authentication Context Decl: (none)

Attributes
givenName: redacted
mail: redacted
surname: redacted

shibboleth2.xml

<SPConfig 
        xmlns="urn:mace:shibboleth:3.0:native:sp:config" 
        xmlns:conf="urn:mace:shibboleth:3.0:native:sp:config" 
        xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion" 
        xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol" 
        xmlns:md="urn:oasis:names:tc:SAML:2.0:metadata"
        clockSkew="180">
        <RequestMapper type="XML">
                <RequestMap applicationId="default">
                        <Host name="https://myDomain.com" authType="shibboleth" requireSession="true" redirectToS>
                                <Path name="auth/login/callback"/>
                                <Path name="user/login" requireSession="false"/>
                        </Host>
                </RequestMap>
        </RequestMapper>
        <ApplicationDefaults entityID="https://myDomain.com/shibboleth" homeURL="/" REMOTE_USER="eppn persistent->
                <Sessions handlerURL="https://myDomain.com/Shibboleth.sso" lifetime="28800" timeout="3600" relayS>
                        <SSO entityID="https://redactedIdP.com/idp/shibboleth">SAML2 SAML1</SSO>
                        <Logout>SAML2 Local</Logout>
                        <Handler type="MetadataGenerator" Location="/Metadata" signing="true"/>
                        <Handler type="Status" Location="/Status" acl="127.0.0.1 ::1"/>
                        <Handler type="Session" Location="/Session" showAttributeValues="true"/>
                        <Handler type="DiscoveryFeed" Location="/DiscoFeed"/>
                </Sessions>
                <Errors supportContact="alex@sitefulstudios.com" helpLocation="/about.html" styleSheet="/shibboleth-s>
                <MetadataProvider type="XML" url="https://redactedIdP.com/idp/CSUS-IdP-metadata.txt" backingFilePath="cs>
                <AttributeExtractor type="XML" validate="true" path="attribute-map.xml"/>
                <AttributeResolver type="Query" subjectMatch="true"/>
                <AttributeFilter type="XML" validate="true" path="attribute-policy.xml"/>
                <CredentialResolver type="File" use="signing"  key="sp-signing-key.pem" certificate="sp-signing-cert.>
                <CredentialResolver type="File" use="encryption"  key="sp-encrypt-key.pem" certificate="sp-encrypt-ce>
        </ApplicationDefaults>
        <SecurityPolicyProvider type="XML" validate="true" path="security-policy.xml"/>
        <ProtocolProvider type="XML" validate="true" reloadChanges="false" path="protocols.xml"/>
</SPConfig>

NGINX Conf

        location = /shibauthorizer {
            internal;
            include fastcgi_params;
            fastcgi_pass unix:/var/run/shibboleth/shibauthorizer.sock;
        }

        location /Shibboleth.sso {
            include fastcgi_params;
            fastcgi_pass unix:/var/run/shibboleth/shibresponder.sock;
        }

        location /auth/login/callback {
           include /root/nginx-http-shibboleth/includes/shib_clear_headers;
           shib_request_use_headers on;
           shib_request /shibauthorizer;
           more_clear_input_headers 'Mail' 'mail' 'Shib-*';
           proxy_pass http://localhost:8080;
        }

        location / {
                proxy_pass http://localhost:8080;
        }

shib_fastcgi_params

shib_request_set $shib_surname $upstream_http_variable_surname;
fastcgi_param Surname $shib_surname;

shib_request_set $shib_givenName $upstream_http_variable_givenName;
fastcgi_param GivenName $shib_givenName;

shib_request_set $shib_mail $upstream_http_variable_mail;
fastcgi_param Mail $shib_mail;

shib_request_set $shib_telephoneNumber $upstream_http_variable_telephoneNumber;
fastcgi_param TelephoneNumber $shib_telephoneNumber;

Relevant Shibd.log

2020-12-11 22:44:22 DEBUG XMLTooling.TrustEngine.ExplicitKey [1] [default]: attempting to validate signature with the peer's credentials
2020-12-11 22:44:22 DEBUG XMLTooling.TrustEngine.ExplicitKey [1] [default]: signature validated with credential
2020-12-11 22:44:22 DEBUG OpenSAML.SecurityPolicyRule.XMLSigning [1] [default]: signature verified against message issuer
2020-12-11 22:44:22 DEBUG Shibboleth.SSO.SAML2 [1] [default]: processing message against SAML 2.0 SSO profile
2020-12-11 22:44:22 DEBUG XMLTooling.CredentialCriteria [1] [default]: usage didn't match (4 != 3)
2020-12-11 22:44:22 DEBUG XMLTooling.CredentialCriteria [1] [default]: key algorithm didn't match ('AES' != 'RSA')
2020-12-11 22:44:22 DEBUG XMLTooling.CredentialCriteria [1] [default]: usage didn't match (4 != 3)
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:Assertion
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:Issuer
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:Subject
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:NameID
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:SubjectConfirmation
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:SubjectConfirmationData
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:Conditions
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:AudienceRestriction
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:Audience
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:AuthnStatement
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:SubjectLocality
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:AuthnContext
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:AuthnContextClassRef
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:AttributeStatement
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:Attribute
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:AttributeValue
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:Attribute
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:AttributeValue
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:Attribute
2020-12-11 22:44:22 DEBUG XMLTooling.XMLObjectBuilder [1] [default]: located XMLObjectBuilder for element name: saml2:AttributeValue
2020-12-11 22:44:22 DEBUG Shibboleth.SSO.SAML2 [1] [default]: decrypted Assertion: <saml2:Assertion xmlns:saml2="urn:oasis:names:tc:SAML:2.0:assertion" ID="_c55cbaa44e11604fd6f99921242f6677" IssueInstant="2020-12-11T22:44:22.380Z" Version="2.0"><saml2:Issuer>https://redactedIdp.com/i>
2020-12-11 22:44:22 DEBUG Shibboleth.SSO.SAML2 [1] [default]: extracting issuer from SAML 2.0 assertion
2020-12-11 22:44:22 DEBUG OpenSAML.SecurityPolicyRule.MessageFlow [1] [default]: evaluating message flow policy (replay checking on, expiration 60)
2020-12-11 22:44:22 DEBUG XMLTooling.StorageService [1] [default]: inserted record (_c55cbaa44e11604fd6f99921242f6677) in context (MessageFlow) with expiration (1607726902)
2020-12-11 22:44:22 DEBUG OpenSAML.SecurityPolicyRule.BearerConfirmation [1] [default]: assertion satisfied bearer confirmation requirements
2020-12-11 22:44:22 DEBUG Shibboleth.SSO.SAML2 [1] [default]: SSO profile processing completed successfully
2020-12-11 22:44:22 DEBUG Shibboleth.SSO.SAML2 [1] [default]: extracting pushed attributes...
2020-12-11 22:44:22 DEBUG Shibboleth.AttributeExtractor.XML [1] [default]: unable to extract attributes, unknown XML object type: saml2p:Response
2020-12-11 22:44:22 DEBUG Shibboleth.AttributeExtractor.XML [1] [default]: skipping unmapped NameID with format (urn:oasis:names:tc:SAML:2.0:nameid-format:transient)
2020-12-11 22:44:22 DEBUG Shibboleth.AttributeExtractor.XML [1] [default]: unable to extract attributes, unknown XML object type: saml2:AuthnStatement
2020-12-11 22:44:22 DEBUG Shibboleth.AttributeDecoder.String [1] [default]: decoding SimpleAttribute (surname) from SAML 2 Attribute (urn:oid:2.5.4.4) with 1 value(s)
2020-12-11 22:44:22 DEBUG Shibboleth.AttributeDecoder.String [1] [default]: decoding SimpleAttribute (givenName) from SAML 2 Attribute (urn:oid:2.5.4.42) with 1 value(s)
2020-12-11 22:44:22 DEBUG Shibboleth.AttributeDecoder.String [1] [default]: decoding SimpleAttribute (mail) from SAML 2 Attribute (urn:oid:0.9.2342.19200300.100.1.3) with 1 value(s)
2020-12-11 22:44:22 DEBUG Shibboleth.SessionCache [1] [default]: creating new session
2020-12-11 22:44:22 DEBUG Shibboleth.SessionCache [1] [default]: storing new session...
2020-12-11 22:44:22 DEBUG XMLTooling.StorageService [1] [default]: inserted record (session) in context (_1b5d4239ee706b76480638a4ef1623e0) with expiration (1607730262)
2020-12-11 22:44:22 DEBUG XMLTooling.StorageService [1] [default]: inserted record (AAdzZWNyZXQxg5lJpn95zwOETmH1J8MlDoq7oIlwvz3eBEjyCDxwVx2FWGIUckxDyxlcpMIbYr99c5vf8fRt9T8hdoPpDqHUE9BOv7S1y4aSuCz4enpi09KX3jjpDEpCIj8CDgVs52QQljunv0yErpEoZp8JGagcWw==) in context (NameID) with expira>
2020-12-11 22:44:22 INFO Shibboleth.SessionCache [1] [default]: new session created: ID (_1b5d4239ee706b76480638a4ef1623e0) IdP (https://redactedIdp.com/idp/shibboleth) Protocol(urn:oasis:names:tc:SAML:2.0:protocol) Address (76.114.21.179)
2020-12-11 22:44:22 DEBUG XMLTooling.StorageService [1] [default]: deleted record (2848ba1bcfb0b42173e3fe70a78627b53daf6e38a4d619d3185a03514655a429) in context (RelayState)
2020-12-11 22:44:22 DEBUG Shibboleth.SSO.SAML2 [1] [default]: ACS returning via redirect to: https://myDomain.com/auth/login/callback
2020-12-11 22:56:05 DEBUG Shibboleth.Listener [1] [default]: dispatching message (find::StorageService::SessionCache)
2020-12-11 22:56:05 DEBUG XMLTooling.StorageService [1] [default]: updated expiration of valid records in context (_1b5d4239ee706b76480638a4ef1623e0) to (1607730965)
2020-12-11 22:58:26 INFO XMLTooling.StorageService : purged 2 expired record(s) from storage

Nginx Logs

Server: nginx/1.18.0
Date: Fri, 11 Dec 2020 22:44:18 GMT
Content-Type: text/html
Content-Length: 40
Connection: keep-alive
Location: https://redactedIdP.com/idp/profile/SAML2/Redirect/SSO?SAMLRequest=fZLNbsIwEIRfJfKdOImIoBZBonAoEi0RoT30UsX20lhN7NRr9%2BftmxDa0kM5Wp6d2fm0MyybumUL7yq9g1cP6IKPptbIjh8Z8VYzU6JCpssGkDnBisXthiVhxFprnBGmJsECEaxTRi%2BNRt%2BALcC%2BKQH3u01GKudaZJQK9CgqEC%2FGu1CYhhaV4tzU4KoQ0dDeN6H5ttiTYNUtonTZW%2F4aKNmGvUkI0vcP2i1wUDWcJncglQXhaFFsSbBeZeRpysXkIPlYxPwgJZ9epZFM0%2FSQlpPphEveyRA9rDW6UruMJFESjeJkFMf7JGHjMYunjyTITz2vlZZKP1%2BGwgcRspv9Ph8NbR7A4rFJJyDzWY%2BWHYPtGezLtuU3YTL%2Flyf%2B8JzRs4whsGV3nel6lZtaic9gUdfmfWmhdJCRmND5MPL3FOZf&RelayState=ss%3Amem%3A2848ba1bcfb0b42173e3fe70a78627b53daf6e38a4d619d3185a03514655a429
Expires: Wed, 01 Jan 1997 12:00:00 GMT
Cache-Control: private,no-store,no-cache,max-age=0

2020/12/11 22:44:18 [debug] 191288#0: *7 write new buf t:1 f:0 000055C29FADA0F0, pos 000055C29FADA0F0, size: 861 file: 0, size: 0
2020/12/11 22:44:18 [debug] 191288#0: *7 http write filter: l:0 f:0 s:861
2020/12/11 22:44:18 [debug] 191288#0: *7 http cacheable: 0
2020/12/11 22:44:18 [debug] 191288#0: *7 http upstream process upstream
2020/12/11 22:44:18 [debug] 191288#0: *7 pipe read upstream: 1
2020/12/11 22:44:18 [debug] 191288#0: *7 pipe preread: 71
2020/12/11 22:44:18 [debug] 191288#0: *7 readv: eof:1, avail:0
2020/12/11 22:44:18 [debug] 191288#0: *7 readv: 1, last:3240
2020/12/11 22:44:18 [debug] 191288#0: *7 pipe recv chain: 0
2020/12/11 22:44:18 [debug] 191288#0: *7 pipe buf free s:0 t:1 f:0 000055C29FAD8CE0, pos 000055C29FAD8FF1, size: 71 file: 0, size: 0
2020/12/11 22:44:18 [debug] 191288#0: *7 pipe length: -1
2020/12/11 22:44:18 [debug] 191288#0: *7 input buf #0 000055C29FAD8FF1
2020/12/11 22:44:18 [debug] 191288#0: *7 http fastcgi record length: 0
2020/12/11 22:44:18 [debug] 191288#0: *7 http fastcgi closed stdout
2020/12/11 22:44:18 [debug] 191288#0: *7 http fastcgi record length: 8
2020/12/11 22:44:18 [debug] 191288#0: *7 http fastcgi sent end request
2020/12/11 22:44:18 [debug] 191288#0: *7 input buf 000055C29FAD8FF1 40
2020/12/11 22:44:18 [debug] 191288#0: *7 pipe write downstream: 1
2020/12/11 22:44:18 [debug] 191288#0: *7 pipe write downstream flush in
2020/12/11 22:44:18 [debug] 191288#0: *7 http output filter "/Shibboleth.sso/Login?target=https://myDomain.com/auth/login/callback"
2020/12/11 22:44:18 [debug] 191288#0: *7 http copy filter: "/Shibboleth.sso/Login?target=https://myDomain.com/auth/login/callback"
2020/12/11 22:44:18 [debug] 191288#0: *7 http postpone filter "/Shibboleth.sso/Login?target=https://myDomain.com/auth/login/callback" 000055C29FADA568
2020/12/11 22:44:18 [debug] 191288#0: *7 write old buf t:1 f:0 000055C29FADA0F0, pos 000055C29FADA0F0, size: 861 file: 0, size: 0
2020/12/11 22:44:18 [debug] 191288#0: *7 write new buf t:1 f:0 000055C29FAD8CE0, pos 000055C29FAD8FF1, size: 40 file: 0, size: 0
2020/12/11 22:44:18 [debug] 191288#0: *7 http write filter: l:0 f:0 s:901
2020/12/11 22:44:18 [debug] 191288#0: *7 http copy filter: 0 "/Shibboleth.sso/Login?target=https://myDomain.com/auth/login/callback"
2020/12/11 22:44:18 [debug] 191288#0: *7 pipe write downstream done
2020/12/11 22:44:18 [debug] 191288#0: *7 event timer: 18, old: 2584329693, new: 2584329693
2020/12/11 22:44:18 [debug] 191288#0: *7 http upstream exit: 0000000000000000
2020/12/11 22:44:18 [debug] 191288#0: *7 finalize http upstream request: 0
2020/12/11 22:44:18 [debug] 191288#0: *7 finalize http fastcgi request
2020/12/11 22:44:18 [debug] 191288#0: *7 free rr peer 1 0
2020/12/11 22:44:18 [debug] 191288#0: *7 close http upstream connection: 18
2020/12/11 22:44:18 [debug] 191288#0: *7 free: 000055C29FADC8D0, unused: 48
2020/12/11 22:44:18 [debug] 191288#0: *7 event timer del: 18: 2584329693
2020/12/11 22:44:18 [debug] 191288#0: *7 reusable connection: 0
2020/12/11 22:44:18 [debug] 191288#0: *7 http upstream temp fd: -1
2020/12/11 22:44:18 [debug] 191288#0: *7 http output filter "/Shibboleth.sso/Login?target=https://myDomain.com/auth/login/callback"
2020/12/11 22:44:18 [debug] 191288#0: *7 http copy filter: "/Shibboleth.sso/Login?target=https://myDomain.com/auth/login/callback"
2020/12/11 22:44:18 [debug] 191288#0: *7 http postpone filter "/Shibboleth.sso/Login?target=https://myDomain.com/auth/login/callback" 00007FFED659C660
2020/12/11 22:44:18 [debug] 191288#0: *7 write old buf t:1 f:0 000055C29FADA0F0, pos 000055C29FADA0F0, size: 861 file: 0, size: 0
2020/12/11 22:44:18 [debug] 191288#0: *7 write old buf t:1 f:0 000055C29FAD8CE0, pos 000055C29FAD8FF1, size: 40 file: 0, size: 0
2020/12/11 22:44:18 [debug] 191288#0: *7 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2020/12/11 22:44:18 [debug] 191288#0: *7 http write filter: l:1 f:0 s:901
2020/12/11 22:44:18 [debug] 191288#0: *7 http write filter limit 0
2020/12/11 22:44:18 [debug] 191288#0: *7 malloc: 000055C29FAEFC70:16384
2020/12/11 22:44:18 [debug] 191288#0: *7 SSL buf copy: 861
2020/12/11 22:44:18 [debug] 191288#0: *7 SSL buf copy: 40
2020/12/11 22:44:18 [debug] 191288#0: *7 SSL to write: 901
2020/12/11 22:44:18 [debug] 191288#0: *7 SSL_write: 901
2020/12/11 22:44:18 [debug] 191288#0: *7 http write filter 0000000000000000
2020/12/11 22:44:18 [debug] 191288#0: *7 http copy filter: 0 "/Shibboleth.sso/Login?target=https://myDomain.com/auth/login/callback"
2020/12/11 22:44:18 [debug] 191288#0: *7 http finalize request: 0, "/Shibboleth.sso/Login?target=https://myDomain.com/auth/login/callback" a:1, c:1
2020/12/11 22:44:18 [debug] 191288#0: *7 set http keepalive handler
2020/12/11 22:44:18 [debug] 191288#0: *7 http close request
2020/12/11 22:44:18 [debug] 191288#0: *7 http log handler
2020/12/11 22:44:18 [debug] 191288#0: *7 free: 000055C29FAD8CE0
2020/12/11 22:44:18 [debug] 191288#0: *7 free: 000055C29FAE04D0, unused: 0
2020/12/11 22:44:18 [debug] 191288#0: *7 free: 000055C29FADB180, unused: 8
2020/12/11 22:44:18 [debug] 191288#0: *7 free: 000055C29FAD9CF0, unused: 1293
2020/12/11 22:44:18 [debug] 191288#0: *7 free: 000055C29FA96410
2020/12/11 22:44:18 [debug] 191288#0: *7 hc free: 0000000000000000
2020/12/11 22:44:18 [debug] 191288#0: *7 hc busy: 0000000000000000 0
2020/12/11 22:44:18 [debug] 191288#0: *7 free: 000055C29FAEFC70
2020/12/11 22:44:18 [debug] 191288#0: *7 reusable connection: 1
2020/12/11 22:44:18 [debug] 191288#0: *7 event timer add: 14: 65000:2584334693
2020/12/11 22:44:22 [debug] 191288#0: *7 http keepalive handler
2020/12/11 22:44:22 [debug] 191288#0: *7 malloc: 000055C29FA96410:1024
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_read: 694
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_read: -1
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_get_error: 2
2020/12/11 22:44:22 [debug] 191288#0: *7 reusable connection: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 posix_memalign: 000055C29FADB180:4096 @16
2020/12/11 22:44:22 [debug] 191288#0: *7 event timer del: 14: 2584334693
2020/12/11 22:44:22 [debug] 191288#0: *7 http process request line
2020/12/11 22:44:22 [debug] 191288#0: *7 http request line: "POST /Shibboleth.sso/SAML2/POST HTTP/1.1"
2020/12/11 22:44:22 [debug] 191288#0: *7 http uri: "/Shibboleth.sso/SAML2/POST"
2020/12/11 22:44:22 [debug] 191288#0: *7 http args: ""
2020/12/11 22:44:22 [debug] 191288#0: *7 http exten: ""
2020/12/11 22:44:22 [debug] 191288#0: *7 posix_memalign: 000055C29FAE04D0:4096 @16
2020/12/11 22:44:22 [debug] 191288#0: *7 http process request header line
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Host: myDomain.com"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Connection: keep-alive"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Content-Length: 13022"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Cache-Control: max-age=0"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Upgrade-Insecure-Requests: 1"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Origin: https://redactedIdP.com"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Content-Type: application/x-www-form-urlencoded"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.66 Safari/537.36"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Sec-Fetch-Site: cross-site"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Sec-Fetch-Mode: navigate"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Sec-Fetch-Dest: document"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Referer: https://redactedIdP.com/"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Accept-Encoding: gzip, deflate, br"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Accept-Language: en-US,en;q=0.9"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header done
2020/12/11 22:44:22 [debug] 191288#0: *7 rewrite phase: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 test location: "/"
2020/12/11 22:44:22 [debug] 191288#0: *7 test location: "auth/login/callback"
2020/12/11 22:44:22 [debug] 191288#0: *7 test location: "Shibboleth.sso"
2020/12/11 22:44:22 [debug] 191288#0: *7 using configuration "/Shibboleth.sso"
2020/12/11 22:44:22 [debug] 191288#0: *7 http cl:13022 max:1048576
2020/12/11 22:44:22 [debug] 191288#0: *7 rewrite phase: 2
2020/12/11 22:44:22 [debug] 191288#0: *7 rewrite phase: 3
2020/12/11 22:44:22 [debug] 191288#0: *7 headers more rewrite handler, uri "/Shibboleth.sso/SAML2/POST"
2020/12/11 22:44:22 [debug] 191288#0: *7 post rewrite phase: 4
2020/12/11 22:44:22 [debug] 191288#0: *7 generic phase: 5
2020/12/11 22:44:22 [debug] 191288#0: *7 generic phase: 6
2020/12/11 22:44:22 [debug] 191288#0: *7 access phase: 7
2020/12/11 22:44:22 [debug] 191288#0: *7 access phase: 8
2020/12/11 22:44:22 [debug] 191288#0: *7 access phase: 9
2020/12/11 22:44:22 [debug] 191288#0: *7 post access phase: 10
2020/12/11 22:44:22 [debug] 191288#0: *7 generic phase: 11
2020/12/11 22:44:22 [debug] 191288#0: *7 generic phase: 12
2020/12/11 22:44:22 [debug] 191288#0: *7 http request body content length filter
2020/12/11 22:44:22 [debug] 191288#0: *7 malloc: 000055C29FAD8CE0:8192
2020/12/11 22:44:22 [debug] 191288#0: *7 http read client request body
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_read: -1
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_get_error: 2
2020/12/11 22:44:22 [debug] 191288#0: *7 http client request body recv -2
2020/12/11 22:44:22 [debug] 191288#0: *7 http client request body rest 13022
2020/12/11 22:44:22 [debug] 191288#0: *7 event timer add: 14: 60000:2584333749
2020/12/11 22:44:22 [debug] 191288#0: *7 http finalize request: -4, "/Shibboleth.sso/SAML2/POST?" a:1, c:2
2020/12/11 22:44:22 [debug] 191288#0: *7 http request count:2 blk:0
2020/12/11 22:44:22 [debug] 191288#0: *7 http run request: "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http request empty handler
2020/12/11 22:44:22 [debug] 191288#0: *7 http run request: "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http read client request body
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_read: -1
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_get_error: 2
2020/12/11 22:44:22 [debug] 191288#0: *7 http client request body recv -2
2020/12/11 22:44:22 [debug] 191288#0: *7 http client request body rest 13022
2020/12/11 22:44:22 [debug] 191288#0: *7 event timer: 14, old: 2584333749, new: 2584333753
2020/12/11 22:44:22 [debug] 191288#0: *7 http run request: "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http request empty handler
2020/12/11 22:44:22 [debug] 191288#0: *7 http run request: "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http request empty handler
2020/12/11 22:44:22 [debug] 191288#0: *7 http run request: "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http read client request body
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_read: -1
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_get_error: 2
2020/12/11 22:44:22 [debug] 191288#0: *7 http client request body recv -2
2020/12/11 22:44:22 [debug] 191288#0: *7 http client request body rest 13022
2020/12/11 22:44:22 [debug] 191288#0: *7 event timer: 14, old: 2584333749, new: 2584333753
2020/12/11 22:44:22 [debug] 191288#0: *7 http run request: "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http request empty handler
2020/12/11 22:44:22 [debug] 191288#0: *7 http run request: "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http read client request body
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_read: 8192
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_read: avail:0
2020/12/11 22:44:22 [debug] 191288#0: *7 http client request body recv 8192
2020/12/11 22:44:22 [debug] 191288#0: *7 http body new buf t:1 f:0 000055C29FAD8CE0, pos 000055C29FAD8CE0, size: 8192 file: 0, size: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http write client request body, bufs 000055C29FAE0E10
2020/12/11 22:44:22 [debug] 191288#0: *7 add cleanup: 000055C29FAE0F48
2020/12/11 22:44:22 [debug] 191288#0: *7 hashed path: /usr/local/nginx/client_body_temp/0000000001
2020/12/11 22:44:22 [debug] 191288#0: *7 temp fd:18
2020/12/11 22:44:22 [warn] 191288#0: *7 a client request body is buffered to a temporary file /usr/local/nginx/client_body_temp/0000000001, client: redactedIP, server: myDomain.com, request: "POST /Shibboleth.sso/SAML2/POST HTTP/1.1", host: "myDomain.com", referrer: "https://redactedIdP.com/"
2020/12/11 22:44:22 [debug] 191288#0: *7 write: 18, 000055C29FAD8CE0, 8192, 0
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_read: 4830
2020/12/11 22:44:22 [debug] 191288#0: *7 post event 000055C29FAA72B0
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_read: avail:0
2020/12/11 22:44:22 [debug] 191288#0: *7 http client request body recv 4830
2020/12/11 22:44:22 [debug] 191288#0: *7 http body new buf t:1 f:0 000055C29FAD8CE0, pos 000055C29FAD8CE0, size: 4830 file: 0, size: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http write client request body, bufs 000055C29FAE0E10
2020/12/11 22:44:22 [debug] 191288#0: *7 write: 18, 000055C29FAD8CE0, 4830, 8192
2020/12/11 22:44:22 [debug] 191288#0: *7 http client request body rest 0
2020/12/11 22:44:22 [debug] 191288#0: *7 event timer del: 14: 2584333749
2020/12/11 22:44:22 [debug] 191288#0: *7 http init upstream, client timer: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 posix_memalign: 000055C29FAEFC70:4096 @16
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "QUERY_STRING"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "QUERY_STRING: "
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "REQUEST_METHOD"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "POST"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "REQUEST_METHOD: POST"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "CONTENT_TYPE"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "application/x-www-form-urlencoded"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "CONTENT_TYPE: application/x-www-form-urlencoded"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "CONTENT_LENGTH"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "13022"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "CONTENT_LENGTH: 13022"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "SCRIPT_NAME"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "/Shibboleth.sso/SAML2/POST"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "SCRIPT_NAME: /Shibboleth.sso/SAML2/POST"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "REQUEST_URI"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "/Shibboleth.sso/SAML2/POST"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "REQUEST_URI: /Shibboleth.sso/SAML2/POST"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "DOCUMENT_URI"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "/Shibboleth.sso/SAML2/POST"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "DOCUMENT_URI: /Shibboleth.sso/SAML2/POST"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "DOCUMENT_ROOT"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "/var/www/redacted"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "DOCUMENT_ROOT: /var/www/redacted"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "SERVER_PROTOCOL"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "HTTP/1.1"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "SERVER_PROTOCOL: HTTP/1.1"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "REQUEST_SCHEME"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "https"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "REQUEST_SCHEME: https"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "HTTPS"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "on"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTPS: on"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "GATEWAY_INTERFACE"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "CGI/1.1"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "GATEWAY_INTERFACE: CGI/1.1"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "SERVER_SOFTWARE"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "nginx/"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "1.18.0"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "SERVER_SOFTWARE: nginx/1.18.0"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "REMOTE_ADDR"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "redactedIP"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "REMOTE_ADDR: redactedIP"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "REMOTE_PORT"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "44147"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "REMOTE_PORT: 44147"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "SERVER_ADDR"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "redactedIP"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "SERVER_ADDR: redactedIP"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "SERVER_PORT"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "443"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "SERVER_PORT: 443"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "SERVER_NAME"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "myDomain.com"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "SERVER_NAME: myDomain.com"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "REDIRECT_STATUS"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "200"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "REDIRECT_STATUS: 200"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_HOST: myDomain.com"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_CONNECTION: keep-alive"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_CONTENT_LENGTH: 13022"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_CACHE_CONTROL: max-age=0"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_UPGRADE_INSECURE_REQUESTS: 1"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_ORIGIN: https://redactedIdP.com"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_CONTENT_TYPE: application/x-www-form-urlencoded"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_USER_AGENT: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.66 Safari/537.36"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_ACCEPT: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_SEC_FETCH_SITE: cross-site"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_SEC_FETCH_MODE: navigate"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_SEC_FETCH_DEST: document"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_REFERER: https://redactedIdP.com/"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_ACCEPT_ENCODING: gzip, deflate, br"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_ACCEPT_LANGUAGE: en-US,en;q=0.9"
2020/12/11 22:44:22 [debug] 191288#0: *7 http cleanup add: 000055C29FAE1180
2020/12/11 22:44:22 [debug] 191288#0: *7 get rr peer, try: 1
2020/12/11 22:44:22 [debug] 191288#0: *7 stream socket 19
2020/12/11 22:44:22 [debug] 191288#0: *7 epoll add connection: fd:19 ev:80002005
2020/12/11 22:44:22 [debug] 191288#0: *7 connect to unix:/var/run/shibboleth/shibresponder.sock, fd:19 #27
2020/12/11 22:44:22 [debug] 191288#0: *7 connected
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream connect: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 posix_memalign: 000055C29FADC8D0:128 @16
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream send request
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream send request body
2020/12/11 22:44:22 [debug] 191288#0: *7 chain writer buf fl:0 s:1240
2020/12/11 22:44:22 [debug] 191288#0: *7 chain writer buf fl:0 s:13022
2020/12/11 22:44:22 [debug] 191288#0: *7 chain writer buf fl:0 s:10
2020/12/11 22:44:22 [debug] 191288#0: *7 chain writer in: 000055C29FAE1200
2020/12/11 22:44:22 [debug] 191288#0: *7 writev: 1240 of 1240
2020/12/11 22:44:22 [debug] 191288#0: *7 sendfile: @0 13022
2020/12/11 22:44:22 [debug] 191288#0: *7 sendfile: 13022 of 13022 @0
2020/12/11 22:44:22 [debug] 191288#0: *7 writev: 10 of 10
2020/12/11 22:44:22 [debug] 191288#0: *7 chain writer out: 0000000000000000
2020/12/11 22:44:22 [debug] 191288#0: *7 event timer add: 19: 60000:2584333773
2020/12/11 22:44:22 [debug] 191288#0: *7 http run request: "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream check client, write event:1, "/Shibboleth.sso/SAML2/POST"
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream request: "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream dummy handler
2020/12/11 22:44:22 [debug] 191288#0: *7 delete posted event 000055C29FAA72B0
2020/12/11 22:44:22 [debug] 191288#0: *7 http run request: "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream check client, write event:0, "/Shibboleth.sso/SAML2/POST"
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream request: "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream process header
2020/12/11 22:44:22 [debug] 191288#0: *7 malloc: 000055C29FAF0C80:4096
2020/12/11 22:44:22 [debug] 191288#0: *7 recv: eof:1, avail:-1
2020/12/11 22:44:22 [debug] 191288#0: *7 recv: fd:19 464 of 4096
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi record length: 431
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi parser: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi header: "Status: 302 Please Wait"
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi parser: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi header: "Location: https://myDomain.com/auth/login/callback"
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi parser: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi header: "Content-Type: text/html"
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi parser: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi header: "Content-Length: 40"
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi parser: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi header: "Expires: Wed, 01 Jan 1997 12:00:00 GMT"
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi parser: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi header: "Cache-Control: private,no-store,no-cache,max-age=0"
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi parser: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi header: "Set-Cookie: _shibsession_64656661756c7468747470733a2f2f63737573636865636b6f75742e636f6d2f73686962626f6c657468=_1b5d4239ee706b76480638a4ef1623e0; path=/; secure; HttpOnly"
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi parser: 1
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi header done
2020/12/11 22:44:22 [debug] 191288#0: *7 HTTP/1.1 302 Please Wait
Server: nginx/1.18.0
Date: Fri, 11 Dec 2020 22:44:22 GMT
Content-Type: text/html
Content-Length: 40
Connection: keep-alive
Location: https://myDomain.com/auth/login/callback
Expires: Wed, 01 Jan 1997 12:00:00 GMT
Cache-Control: private,no-store,no-cache,max-age=0
Set-Cookie: _shibsession_64656661756c7468747470733a2f2f63737573636865636b6f75742e636f6d2f73686962626f6c657468=_1b5d4239ee706b76480638a4ef1623e0; path=/; secure; HttpOnly

2020/12/11 22:44:22 [debug] 191288#0: *7 write new buf t:1 f:0 000055C29FAF02F0, pos 000055C29FAF02F0, size: 475 file: 0, size: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http write filter: l:0 f:0 s:475
2020/12/11 22:44:22 [debug] 191288#0: *7 file cleanup: fd:18
2020/12/11 22:44:22 [debug] 191288#0: *7 http cacheable: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream process upstream
2020/12/11 22:44:22 [debug] 191288#0: *7 pipe read upstream: 1
2020/12/11 22:44:22 [debug] 191288#0: *7 pipe preread: 65
2020/12/11 22:44:22 [debug] 191288#0: *7 readv: eof:1, avail:0
2020/12/11 22:44:22 [debug] 191288#0: *7 readv: 1, last:3632
2020/12/11 22:44:22 [debug] 191288#0: *7 pipe recv chain: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 pipe buf free s:0 t:1 f:0 000055C29FAF0C80, pos 000055C29FAF0E0F, size: 65 file: 0, size: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 pipe length: -1
2020/12/11 22:44:22 [debug] 191288#0: *7 input buf #0 000055C29FAF0E0F
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi record length: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi closed stdout
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi record length: 8
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi sent end request
2020/12/11 22:44:22 [debug] 191288#0: *7 input buf 000055C29FAF0E0F 40
2020/12/11 22:44:22 [debug] 191288#0: *7 pipe write downstream: 1
2020/12/11 22:44:22 [debug] 191288#0: *7 pipe write downstream flush in
2020/12/11 22:44:22 [debug] 191288#0: *7 http output filter "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http copy filter: "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http postpone filter "/Shibboleth.sso/SAML2/POST?" 000055C29FAE11D0
2020/12/11 22:44:22 [debug] 191288#0: *7 write old buf t:1 f:0 000055C29FAF02F0, pos 000055C29FAF02F0, size: 475 file: 0, size: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 write new buf t:1 f:0 000055C29FAF0C80, pos 000055C29FAF0E0F, size: 40 file: 0, size: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http write filter: l:0 f:0 s:515
2020/12/11 22:44:22 [debug] 191288#0: *7 http copy filter: 0 "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 pipe write downstream done
2020/12/11 22:44:22 [debug] 191288#0: *7 event timer: 19, old: 2584333773, new: 2584333789
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream exit: 0000000000000000
2020/12/11 22:44:22 [debug] 191288#0: *7 finalize http upstream request: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 finalize http fastcgi request
2020/12/11 22:44:22 [debug] 191288#0: *7 free rr peer 1 0
2020/12/11 22:44:22 [debug] 191288#0: *7 close http upstream connection: 19
2020/12/11 22:44:22 [debug] 191288#0: *7 free: 000055C29FADC8D0, unused: 48
2020/12/11 22:44:22 [debug] 191288#0: *7 event timer del: 19: 2584333773
2020/12/11 22:44:22 [debug] 191288#0: *7 reusable connection: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream temp fd: -1
2020/12/11 22:44:22 [debug] 191288#0: *7 http output filter "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http copy filter: "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http postpone filter "/Shibboleth.sso/SAML2/POST?" 00007FFED659C660
2020/12/11 22:44:22 [debug] 191288#0: *7 write old buf t:1 f:0 000055C29FAF02F0, pos 000055C29FAF02F0, size: 475 file: 0, size: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 write old buf t:1 f:0 000055C29FAF0C80, pos 000055C29FAF0E0F, size: 40 file: 0, size: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http write filter: l:1 f:0 s:515
2020/12/11 22:44:22 [debug] 191288#0: *7 http write filter limit 0
2020/12/11 22:44:22 [debug] 191288#0: *7 malloc: 000055C29FAE9840:16384
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL buf copy: 475
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL buf copy: 40
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL to write: 515
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_write: 515
2020/12/11 22:44:22 [debug] 191288#0: *7 http write filter 0000000000000000
2020/12/11 22:44:22 [debug] 191288#0: *7 http copy filter: 0 "/Shibboleth.sso/SAML2/POST?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http finalize request: 0, "/Shibboleth.sso/SAML2/POST?" a:1, c:1
2020/12/11 22:44:22 [debug] 191288#0: *7 set http keepalive handler
2020/12/11 22:44:22 [debug] 191288#0: *7 http close request
2020/12/11 22:44:22 [debug] 191288#0: *7 http log handler
2020/12/11 22:44:22 [debug] 191288#0: *7 free: 000055C29FAF0C80
2020/12/11 22:44:22 [debug] 191288#0: *7 free: 000055C29FAD8CE0
2020/12/11 22:44:22 [debug] 191288#0: *7 free: 000055C29FADB180, unused: 3
2020/12/11 22:44:22 [debug] 191288#0: *7 free: 000055C29FAE04D0, unused: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 free: 000055C29FAEFC70, unused: 1161
2020/12/11 22:44:22 [debug] 191288#0: *7 free: 000055C29FA96410
2020/12/11 22:44:22 [debug] 191288#0: *7 hc free: 0000000000000000
2020/12/11 22:44:22 [debug] 191288#0: *7 hc busy: 0000000000000000 0
2020/12/11 22:44:22 [debug] 191288#0: *7 free: 000055C29FAE9840
2020/12/11 22:44:22 [debug] 191288#0: *7 reusable connection: 1
2020/12/11 22:44:22 [debug] 191288#0: *7 event timer add: 14: 65000:2584338789
2020/12/11 22:44:22 [debug] 191288#0: *7 post event 000055C29FAA72B0
2020/12/11 22:44:22 [debug] 191288#0: *7 delete posted event 000055C29FAA72B0
2020/12/11 22:44:22 [debug] 191288#0: *7 http keepalive handler
2020/12/11 22:44:22 [debug] 191288#0: *7 malloc: 000055C29FA96410:1024
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_read: -1
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_get_error: 2
2020/12/11 22:44:22 [debug] 191288#0: *7 free: 000055C29FA96410
2020/12/11 22:44:22 [debug] 191288#0: *7 http keepalive handler
2020/12/11 22:44:22 [debug] 191288#0: *7 malloc: 000055C29FA96410:1024
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_read: 778
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_read: -1
2020/12/11 22:44:22 [debug] 191288#0: *7 SSL_get_error: 2
2020/12/11 22:44:22 [debug] 191288#0: *7 reusable connection: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 posix_memalign: 000055C29FAE04D0:4096 @16
2020/12/11 22:44:22 [debug] 191288#0: *7 event timer del: 14: 2584338789
2020/12/11 22:44:22 [debug] 191288#0: *7 http process request line
2020/12/11 22:44:22 [debug] 191288#0: *7 http request line: "GET /auth/login/callback HTTP/1.1"
2020/12/11 22:44:22 [debug] 191288#0: *7 http uri: "/auth/login/callback"
2020/12/11 22:44:22 [debug] 191288#0: *7 http args: ""
2020/12/11 22:44:22 [debug] 191288#0: *7 http exten: ""
2020/12/11 22:44:22 [debug] 191288#0: *7 posix_memalign: 000055C29FADB180:4096 @16
2020/12/11 22:44:22 [debug] 191288#0: *7 http process request header line
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Host: myDomain.com"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Connection: keep-alive"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Cache-Control: max-age=0"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Upgrade-Insecure-Requests: 1"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.66 Safari/537.36"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Sec-Fetch-Site: cross-site"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Sec-Fetch-Mode: navigate"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Sec-Fetch-Dest: document"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Referer: https://redactedIdP.com/"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Accept-Encoding: gzip, deflate, br"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Accept-Language: en-US,en;q=0.9"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "Cookie: _shibsession_64656661756c7468747470733a2f2f63737573636865636b6f75742e636f6d2f73686962626f6c657468=_1b5d4239ee706b76480638a4ef1623e0"
2020/12/11 22:44:22 [debug] 191288#0: *7 http header: "If-None-Match: W/"334-LPt9aSJZGPpCUOKKhHq5lS2wuPI""
2020/12/11 22:44:22 [debug] 191288#0: *7 http header done
2020/12/11 22:44:22 [debug] 191288#0: *7 rewrite phase: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 test location: "/"
2020/12/11 22:44:22 [debug] 191288#0: *7 test location: "auth/login/callback"
2020/12/11 22:44:22 [debug] 191288#0: *7 using configuration "/auth/login/callback"
2020/12/11 22:44:22 [debug] 191288#0: *7 http cl:-1 max:1048576
2020/12/11 22:44:22 [debug] 191288#0: *7 rewrite phase: 2
2020/12/11 22:44:22 [debug] 191288#0: *7 rewrite phase: 3
2020/12/11 22:44:22 [debug] 191288#0: *7 headers more rewrite handler, uri "/auth/login/callback"
2020/12/11 22:44:22 [debug] 191288#0: *7 post rewrite phase: 4
2020/12/11 22:44:22 [debug] 191288#0: *7 generic phase: 5
2020/12/11 22:44:22 [debug] 191288#0: *7 generic phase: 6
2020/12/11 22:44:22 [debug] 191288#0: *7 access phase: 7
2020/12/11 22:44:22 [debug] 191288#0: *7 shib request handler
2020/12/11 22:44:22 [debug] 191288#0: *7 http subrequest "/shibauthorizer?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http posted request: "/shibauthorizer?"
2020/12/11 22:44:22 [debug] 191288#0: *7 rewrite phase: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 test location: "/"
2020/12/11 22:44:22 [debug] 191288#0: *7 test location: "auth/login/callback"
2020/12/11 22:44:22 [debug] 191288#0: *7 test location: "shibauthorizer"
2020/12/11 22:44:22 [debug] 191288#0: *7 using configuration "=/shibauthorizer"
2020/12/11 22:44:22 [debug] 191288#0: *7 http cl:-1 max:1048576
2020/12/11 22:44:22 [debug] 191288#0: *7 rewrite phase: 2
2020/12/11 22:44:22 [debug] 191288#0: *7 rewrite phase: 3
2020/12/11 22:44:22 [debug] 191288#0: *7 headers more rewrite handler, uri "/shibauthorizer"
2020/12/11 22:44:22 [debug] 191288#0: *7 post rewrite phase: 4
2020/12/11 22:44:22 [debug] 191288#0: *7 generic phase: 5
2020/12/11 22:44:22 [debug] 191288#0: *7 generic phase: 6
2020/12/11 22:44:22 [debug] 191288#0: *7 generic phase: 11
2020/12/11 22:44:22 [debug] 191288#0: *7 generic phase: 12
2020/12/11 22:44:22 [debug] 191288#0: *7 posix_memalign: 000055C29FAD8CE0:4096 @16
2020/12/11 22:44:22 [debug] 191288#0: *7 http init upstream, client timer: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "QUERY_STRING"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "QUERY_STRING: "
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "REQUEST_METHOD"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "GET"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "REQUEST_METHOD: GET"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "CONTENT_TYPE"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "CONTENT_TYPE: "
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "CONTENT_LENGTH"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "CONTENT_LENGTH: "
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "SCRIPT_NAME"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "/shibauthorizer"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "SCRIPT_NAME: /shibauthorizer"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "REQUEST_URI"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "/auth/login/callback"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "REQUEST_URI: /auth/login/callback"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "DOCUMENT_URI"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "/shibauthorizer"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "DOCUMENT_URI: /shibauthorizer"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "DOCUMENT_ROOT"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "/var/www/redacted"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "DOCUMENT_ROOT: /var/www/redacted"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "SERVER_PROTOCOL"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "HTTP/1.1"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "SERVER_PROTOCOL: HTTP/1.1"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "REQUEST_SCHEME"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "https"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "REQUEST_SCHEME: https"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "HTTPS"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "on"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTPS: on"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "GATEWAY_INTERFACE"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "CGI/1.1"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "GATEWAY_INTERFACE: CGI/1.1"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "SERVER_SOFTWARE"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "nginx/"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "1.18.0"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "SERVER_SOFTWARE: nginx/1.18.0"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "REMOTE_ADDR"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "redactedIP"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "REMOTE_ADDR: redactedIP"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "REMOTE_PORT"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "44147"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "REMOTE_PORT: 44147"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "SERVER_ADDR"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "redactedIP"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "SERVER_ADDR: redactedIP"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "SERVER_PORT"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "443"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "SERVER_PORT: 443"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "SERVER_NAME"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "myDomain.com"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "SERVER_NAME: myDomain.com"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "REDIRECT_STATUS"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "200"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "REDIRECT_STATUS: 200"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_HOST: myDomain.com"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_CONNECTION: keep-alive"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_CACHE_CONTROL: max-age=0"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_UPGRADE_INSECURE_REQUESTS: 1"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_USER_AGENT: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.66 Safari/537.36"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_ACCEPT: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_SEC_FETCH_SITE: cross-site"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_SEC_FETCH_MODE: navigate"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_SEC_FETCH_DEST: document"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_REFERER: https://redactedIdP.com/"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_ACCEPT_ENCODING: gzip, deflate, br"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_ACCEPT_LANGUAGE: en-US,en;q=0.9"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_COOKIE: _shibsession_64656661756c7468747470733a2f2f63737573636865636b6f75742e636f6d2f73686962626f6c657468=_1b5d4239ee706b76480638a4ef1623e0"
2020/12/11 22:44:22 [debug] 191288#0: *7 fastcgi param: "HTTP_IF_NONE_MATCH: W/"334-LPt9aSJZGPpCUOKKhHq5lS2wuPI""
2020/12/11 22:44:22 [debug] 191288#0: *7 http cleanup add: 000055C29FAD9750
2020/12/11 22:44:22 [debug] 191288#0: *7 get rr peer, try: 1
2020/12/11 22:44:22 [debug] 191288#0: *7 stream socket 18
2020/12/11 22:44:22 [debug] 191288#0: *7 epoll add connection: fd:18 ev:80002005
2020/12/11 22:44:22 [debug] 191288#0: *7 connect to unix:/var/run/shibboleth/shibauthorizer.sock, fd:18 #28
2020/12/11 22:44:22 [debug] 191288#0: *7 connected
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream connect: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 posix_memalign: 000055C29FADC8D0:128 @16
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream send request
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream send request body
2020/12/11 22:44:22 [debug] 191288#0: *7 chain writer buf fl:0 s:1264
2020/12/11 22:44:22 [debug] 191288#0: *7 chain writer in: 000055C29FAD9790
2020/12/11 22:44:22 [debug] 191288#0: *7 writev: 1264 of 1264
2020/12/11 22:44:22 [debug] 191288#0: *7 chain writer out: 0000000000000000
2020/12/11 22:44:22 [debug] 191288#0: *7 event timer add: 18: 60000:2584333817
2020/12/11 22:44:22 [debug] 191288#0: *7 http finalize request: -4, "/shibauthorizer?" a:1, c:3
2020/12/11 22:44:22 [debug] 191288#0: *7 http request count:3 blk:0
2020/12/11 22:44:22 [debug] 191288#0: *7 http run request: "/shibauthorizer?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream check client, write event:1, "/shibauthorizer"
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream request: "/shibauthorizer?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http upstream process header
2020/12/11 22:44:22 [debug] 191288#0: *7 malloc: 000055C29FAD9CF0:4096
2020/12/11 22:44:22 [debug] 191288#0: *7 recv: eof:1, avail:-1
2020/12/11 22:44:22 [debug] 191288#0: *7 recv: fd:18 56 of 4096
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi record length: 18
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi parser: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi header: "Status: 200 OK"
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi parser: 1
2020/12/11 22:44:22 [debug] 191288#0: *7 http fastcgi header done
2020/12/11 22:44:22 [debug] 191288#0: *7 finalize http upstream request: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 finalize http fastcgi request
2020/12/11 22:44:22 [debug] 191288#0: *7 free rr peer 1 0
2020/12/11 22:44:22 [debug] 191288#0: *7 close http upstream connection: 18
2020/12/11 22:44:22 [debug] 191288#0: *7 free: 000055C29FADC8D0, unused: 48
2020/12/11 22:44:22 [debug] 191288#0: *7 event timer del: 18: 2584333817
2020/12/11 22:44:22 [debug] 191288#0: *7 reusable connection: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http finalize request: 0, "/shibauthorizer?" a:1, c:2
2020/12/11 22:44:22 [debug] 191288#0: *7 shib request done s:200
2020/12/11 22:44:22 [debug] 191288#0: *7 http wake parent request: "/auth/login/callback?"
2020/12/11 22:44:22 [debug] 191288#0: *7 http posted request: "/auth/login/callback?"
2020/12/11 22:44:22 [debug] 191288#0: *7 access phase: 7
2020/12/11 22:44:22 [debug] 191288#0: *7 shib request handler
2020/12/11 22:44:22 [debug] 191288#0: *7 shib request set variables
2020/12/11 22:44:22 [debug] 191288#0: *7 shib request authorizer handler
2020/12/11 22:44:22 [debug] 191288#0: *7 shib request authorizer allows access
2020/12/11 22:44:22 [debug] 191288#0: *7 access phase: 8
2020/12/11 22:44:22 [debug] 191288#0: *7 access phase: 9
2020/12/11 22:44:22 [debug] 191288#0: *7 post access phase: 10
2020/12/11 22:44:22 [debug] 191288#0: *7 generic phase: 11
2020/12/11 22:44:22 [debug] 191288#0: *7 generic phase: 12
2020/12/11 22:44:22 [debug] 191288#0: *7 posix_memalign: 000055C29FAE9840:4096 @16
2020/12/11 22:44:22 [debug] 191288#0: *7 http init upstream, client timer: 0
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "Debug"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "I came from nginx block /auth/login/callback"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: ""
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: ""
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "Host"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script var: "localhost:8080"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "Connection"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: "close"
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: ""
2020/12/11 22:44:22 [debug] 191288#0: *7 http script copy: ""
2020/12/11 22:44:22 [debug] 191288#0: *7 http proxy header: "Cache-Control: max-age=0"
2020/12/11 22:44:22 [debug] 191288#0: *7 http proxy header: "Upgrade-Insecure-Requests: 1"
2020/12/11 22:44:22 [debug] 191288#0: *7 http proxy header: "User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.66 Safari/537.36"
2020/12/11 22:44:22 [debug] 191288#0: *7 http proxy header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"
2020/12/11 22:44:22 [debug] 191288#0: *7 http proxy header: "Sec-Fetch-Site: cross-site"
2020/12/11 22:44:22 [debug] 191288#0: *7 http proxy header: "Sec-Fetch-Mode: navigate"
2020/12/11 22:44:22 [debug] 191288#0: *7 http proxy header: "Sec-Fetch-Dest: document"
2020/12/11 22:44:22 [debug] 191288#0: *7 http proxy header: "Referer: https://redactedIdP.com/"
2020/12/11 22:44:22 [debug] 191288#0: *7 http proxy header: "Accept-Encoding: gzip, deflate, br"
2020/12/11 22:44:22 [debug] 191288#0: *7 http proxy header: "Accept-Language: en-US,en;q=0.9"
2020/12/11 22:44:22 [debug] 191288#0: *7 http proxy header: "Cookie: _shibsession_64656661756c7468747470733a2f2f63737573636865636b6f75742e636f6d2f73686962626f6c657468=_1b5d4239ee706b76480638a4ef1623e0"
2020/12/11 22:44:22 [debug] 191288#0: *7 http proxy header: "If-None-Match: W/"334-LPt9aSJZGPpCUOKKhHq5lS2wuPI""
2020/12/11 22:44:22 [debug] 191288#0: *7 http proxy header:

Versions and Systems

Ubuntu 20.04.1 LTS
NGINX version: nginx/1.18.0 (I also tried with 1.19.5)
shibboleth 3.0.4

Additional context

If I missed any details let me know and I'll be happy to provide them. I really need to solve this issue. A HUGE thanks in advance!

davidjb commented 3 years ago

It appears as though your Shib authorizer isn't recognising your secured paths to allow the headers through. Check this section of your shibboleth2.xml:

                        <Host name="https://myDomain.com" authType="shibboleth" requireSession="true" redirectToS>
                                <Path name="auth/login/callback"/>
                                <Path name="user/login" requireSession="false"/>
                        </Host>

The <Host> name needs just be the hostname (mydomain.com) and not have a scheme/protocol present -- that looks to be it. You can add a scheme via scheme="https" if you just want to match specifically; otherwise both http and https get matched (https://wiki.shibboleth.net/confluence/display/SP3/Host).

Also, path names don't need to begin with a / but I make mine match nginx exactly. redirectToS needs to be fixed too, which might affect parsing of the node in XML.

asonj commented 3 years ago

@davidjb Dude, you are a wizard. Removing the scheme/protocol fixed it. Thanks a ton. Can I send you a coffee or something?

davidjb commented 3 years ago

Excellent - glad to know that was it. Thanks for the kind offer but just happy to help.