Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

_codexch uses default Client ID / Secret #44

Open
wongkeewee opened this issue Dec 8, 2021 · 8 comments
Open

_codexch uses default Client ID / Secret #44

wongkeewee opened this issue Dec 8, 2021 · 8 comments
Assignees
@tippexs
Labels
enhancement New feature or request question Further information is requested

Comments

@wongkeewee
Copy link

Hi,

I have a requirement to protect different URI on the same reverse proxy with different set of Client ID/Secret and Scopes, for example:

  • /app1 -> ClientID: AAA / ClientSecret: AAA / Scope: scope1
  • /app2 -> ClientID: BBB / ClientSecret: BBB / Scope: scope2

I followed Issue #27 to map using $uri instead of $host

openid_connect_configuration.conf

# OpenID Connect configuration
#
# Each map block allows multiple values so that multiple IdPs can be supported,
# the $host variable is used as the default input parameter but can be changed.
#
map $host $oidc_authz_endpoint {
    rp.company.com https://sso.company.com/oxauth/restv1/authorize;

    default "http://sso.company.com/oxauth/restv1/authorize";
    #www.example.com "https://my-idp/oauth2/v1/authorize";
}

map $host $oidc_token_endpoint {
    rp.company.com https://sso.company.com/oxauth/restv1/token;

    default "https://sso.company.com/oxauth/restv1/token";
}

map $host $oidc_jwt_keyfile {
    rp.company.com https://sso.company.com/oxauth/restv1/jwks;

    default "http://sso.company.com/oxauth/restv1/jwks";
}

map $uri $oidc_client {
    ~^/htvar/(.*)$ client-id-aaa;

    default "my-client-id";
}


map $host $oidc_pkce_enable {
    default 0;
}

map $uri $oidc_client_secret {
    ~^/htvar/(.*)$ "client-secret-aaa";

    default "my-client-secret";
}


map $uri $oidc_scopes {
    ~^/htvar/(.*)$ "openid+profile+email+user_name+user_role+user_type";
    default "openid+profile+email+offline_access";
}


map $host $oidc_logout_redirect {
    # Where to send browser after requesting /logout location. This can be
    # replaced with a custom logout page, or complete URL.
    default "/_logout"; # Built-in, simple logout page
}

map $host $oidc_hmac_key {
    rp.company.com hmac_key;

    # This should be unique for every NGINX instance/cluster
    default "ChangeMe";
}

map $proto $oidc_cookie_flags {
    http  "Path=/; SameSite=lax;"; # For HTTP/plaintext testing
    https "Path=/; SameSite=lax; HttpOnly; Secure;"; # Production recommendation
}

map $http_x_forwarded_port $redirect_base {
    ""      $proto://$host:$server_port;
    default $proto://$host:$http_x_forwarded_port;
}

map $http_x_forwarded_proto $proto {
    ""      $scheme;
    default $http_x_forwarded_proto;
}

# ADVANCED CONFIGURATION BELOW THIS LINE
# Additional advanced configuration (server context) in openid_connect.server_conf

# JWK Set will be fetched from $oidc_jwks_uri and cached here - ensure writable by nginx user
proxy_cache_path /var/cache/nginx/jwk levels=1 keys_zone=jwk:64k max_size=1m;

# Change timeout values to at least the validity period of each token type
keyval_zone zone=oidc_id_tokens:1M state=conf.d/oidc_id_tokens.json timeout=1h;
keyval_zone zone=refresh_tokens:1M state=conf.d/refresh_tokens.json timeout=8h;
keyval_zone zone=oidc_pkce:128K timeout=90s; # Temporary storage for PKCE code verifier.

keyval $cookie_auth_token $session_jwt zone=oidc_id_tokens;   # Exchange cookie for JWT
keyval $cookie_auth_token $refresh_token zone=refresh_tokens; # Exchange cookie for refresh token
keyval $request_id $new_session zone=oidc_id_tokens; # For initial session creation
keyval $request_id $new_refresh zone=refresh_tokens; # ''
keyval $pkce_id $pkce_code_verifier zone=oidc_pkce;

auth_jwt_claim_set $jwt_audience aud; # In case aud is an array
js_import oidc from conf.d/openid_connect.js;

# vim: syntax=nginx

When I access the protected URI, I am prompted to login at my SSO server and redirected back to the callback URI _codexch.
However, the _codexch throws a NGINX / OpenID Connect login failure error.
From the SSO server, I am seeing that the OIDC is attempting to authenticate with my-client-id and my-client-secret, which is the default value in the openid_connect_configuration.conf file.

It seems like it is not picking up the Client ID/Secret for the URI.

The debug output of nginx is:

2021/12/08 16:29:25 [debug] 21315#21315: accept on 0.0.0.0:443, ready: 0
2021/12/08 16:29:25 [debug] 21314#21314: accept on 0.0.0.0:443, ready: 0
2021/12/08 16:29:25 [debug] 21315#21315: posix_memalign: 0000560F14FCEF60:512 @16
2021/12/08 16:29:25 [debug] 21314#21314: accept() not ready (11: Resource temporarily unavailable)
2021/12/08 16:29:25 [debug] 21315#21315: *1 accept: 192.168.0.91:55291 fd:16
2021/12/08 16:29:25 [debug] 21315#21315: *1 event timer add: 16: 60000:429931535
2021/12/08 16:29:25 [debug] 21315#21315: *1 reusable connection: 1
2021/12/08 16:29:25 [debug] 21315#21315: *1 epoll add event: fd:16 op:1 ev:80002001
2021/12/08 16:29:25 [debug] 21315#21315: *1 http check ssl handshake
2021/12/08 16:29:25 [debug] 21315#21315: *1 http recv(): 1
2021/12/08 16:29:25 [debug] 21315#21315: *1 https ssl handshake: 0x16
2021/12/08 16:29:25 [debug] 21315#21315: *1 tcp_nodelay
2021/12/08 16:29:25 [debug] 21315#21315: *1 reusable connection: 0
2021/12/08 16:29:25 [debug] 21315#21315: *1 SSL server name: "rp.company.com"
2021/12/08 16:29:25 [debug] 21315#21315: *1 SSL ALPN supported by client: h2
2021/12/08 16:29:25 [debug] 21315#21315: *1 SSL ALPN supported by client: http/1.1
2021/12/08 16:29:25 [debug] 21315#21315: *1 SSL ALPN selected: http/1.1
2021/12/08 16:29:25 [debug] 21315#21315: *1 SSL_do_handshake: -1
2021/12/08 16:29:25 [debug] 21315#21315: *1 SSL_get_error: 2
2021/12/08 16:29:25 [debug] 21315#21315: *1 SSL handshake handler: 0
2021/12/08 16:29:25 [debug] 21315#21315: *1 SSL_do_handshake: 0
2021/12/08 16:29:25 [debug] 21315#21315: *1 SSL_get_error: 1
2021/12/08 16:29:25 [info] 21315#21315: *1 SSL_do_handshake() failed (SSL: error:14094416:SSL routines:ssl3_read_bytes:sslv3 alert certificate unknown:SSL alert number 46) while SSL handshaking, client: 192.168.0.91, server: 0.0.0.0:443
2021/12/08 16:29:25 [debug] 21315#21315: *1 close http connection: 16
2021/12/08 16:29:25 [debug] 21315#21315: *1 event timer del: 16: 429931535
2021/12/08 16:29:25 [debug] 21315#21315: *1 reusable connection: 0
2021/12/08 16:29:25 [debug] 21315#21315: *1 free: 0000560F14FCEF60, unused: 121
2021/12/08 16:29:25 [debug] 21314#21314: accept on 0.0.0.0:443, ready: 0
2021/12/08 16:29:25 [debug] 21315#21315: accept on 0.0.0.0:443, ready: 0
2021/12/08 16:29:25 [debug] 21315#21315: accept() not ready (11: Resource temporarily unavailable)
2021/12/08 16:29:25 [debug] 21314#21314: posix_memalign: 0000560F14FCEF60:512 @16
2021/12/08 16:29:25 [debug] 21314#21314: *2 accept: 192.168.0.91:55292 fd:16
2021/12/08 16:29:25 [debug] 21314#21314: *2 event timer add: 16: 60000:429931575
2021/12/08 16:29:25 [debug] 21314#21314: *2 reusable connection: 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 epoll add event: fd:16 op:1 ev:80002001
2021/12/08 16:29:25 [debug] 21314#21314: *2 http check ssl handshake
2021/12/08 16:29:25 [debug] 21314#21314: *2 http recv(): 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 https ssl handshake: 0x16
2021/12/08 16:29:25 [debug] 21314#21314: *2 tcp_nodelay
2021/12/08 16:29:25 [debug] 21314#21314: *2 reusable connection: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL server name: "rp.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL ALPN supported by client: h2
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL ALPN supported by client: http/1.1
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL ALPN selected: http/1.1
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_do_handshake: -1
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_get_error: 2
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL handshake handler: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_do_handshake: 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL: TLSv1.2, cipher: "ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(128) Mac=AEAD"
2021/12/08 16:29:25 [debug] 21314#21314: *2 reusable connection: 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 http wait request handler
2021/12/08 16:29:25 [debug] 21314#21314: *2 malloc: 0000560F15052B80:1024
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_read: 764
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_read: -1
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_get_error: 2
2021/12/08 16:29:25 [debug] 21314#21314: *2 reusable connection: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 posix_memalign: 0000560F14F12A60:4096 @16
2021/12/08 16:29:25 [debug] 21314#21314: *2 http process request line
2021/12/08 16:29:25 [debug] 21314#21314: *2 http request line: "GET /htvar/ugly.jsp HTTP/1.1"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http uri: "/htvar/ugly.jsp"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http args: ""
2021/12/08 16:29:25 [debug] 21314#21314: *2 http exten: "jsp"
2021/12/08 16:29:25 [debug] 21314#21314: *2 posix_memalign: 0000560F1504E2C0:4096 @16
2021/12/08 16:29:25 [debug] 21314#21314: *2 http process request header line
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Host: rp.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Connection: keep-alive"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "sec-ch-ua: " Not A;Brand";v="99", "Chromium";v="96", "Google Chrome";v="96""
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "sec-ch-ua-mobile: ?0"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "sec-ch-ua-platform: "Windows""
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "DNT: 1"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Upgrade-Insecure-Requests: 1"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36"
2021/12/08 16:29:25 [debug] 21314#21314: *2 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"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Sec-Fetch-Site: none"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Sec-Fetch-Mode: navigate"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Sec-Fetch-User: ?1"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Sec-Fetch-Dest: document"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Accept-Encoding: gzip, deflate, br"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Accept-Language: en-SG,en;q=0.9"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Cookie: auth_redir=/htvar/ugly.jsp; auth_nonce=f3bfeb7bcc2dc7769eb92b9c81403879"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header done
2021/12/08 16:29:25 [debug] 21314#21314: *2 event timer del: 16: 429931575
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 rewrite phase: 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script value: "NGINX / OpenID Connect login failure
"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script set $internal_error_message
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script value: ""
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script set $pkce_id
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script value: "/_codexch"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script set $redir_location
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "/"
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "_refresh"
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "htvar/"
2021/12/08 16:29:25 [debug] 21314#21314: *2 using configuration "/htvar/"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http cl:-1 max:1048576
2021/12/08 16:29:25 [debug] 21314#21314: *2 rewrite phase: 3
2021/12/08 16:29:25 [debug] 21314#21314: *2 post rewrite phase: 4
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 5
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 6
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 7
2021/12/08 16:29:25 [debug] 21314#21314: *2 access phase: 8
2021/12/08 16:29:25 [debug] 21314#21314: *2 access phase: 9
2021/12/08 16:29:25 [debug] 21314#21314: *2 auth jwt request handler
2021/12/08 16:29:25 [debug] 21314#21314: *2 parse header: "Cookie: auth_redir=/htvar/ugly.jsp; auth_nonce=f3bfeb7bcc2dc7769eb92b9c81403879"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http finalize request: 401, "/htvar/ugly.jsp?" a:1, c:1
2021/12/08 16:29:25 [debug] 21314#21314: *2 http special response: 401, "/htvar/ugly.jsp?"
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "@do_oidc_flow"
2021/12/08 16:29:25 [debug] 21314#21314: *2 using location: @do_oidc_flow "/htvar/ugly.jsp?"
2021/12/08 16:29:25 [debug] 21314#21314: *2 rewrite phase: 3
2021/12/08 16:29:25 [debug] 21314#21314: *2 post rewrite phase: 4
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 5
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 6
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 7
2021/12/08 16:29:25 [debug] 21314#21314: *2 access phase: 8
2021/12/08 16:29:25 [debug] 21314#21314: *2 access phase: 9
2021/12/08 16:29:25 [debug] 21314#21314: *2 access phase: 10
2021/12/08 16:29:25 [debug] 21314#21314: *2 access phase: 11
2021/12/08 16:29:25 [debug] 21314#21314: *2 post access phase: 12
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 13
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 14
2021/12/08 16:29:25 [debug] 21314#21314: *2 add cleanup: 0000560F1504E9B0
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "rp.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "rp.company.com" "https://sso.company.com/oxauth/restv1/authorize"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "rp.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "rp.company.com" "https://sso.company.com/oxauth/restv1/authorize"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "/htvar/ugly.jsp"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "/htvar/ugly.jsp" "openid+profile+email+user_name+user_role+user_type"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "/htvar/ugly.jsp"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "/htvar/ugly.jsp" "openid+profile+email+user_name+user_role+user_type"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "rp.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "rp.company.com" "hmac_key"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "rp.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "rp.company.com" "hmac_key"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "https"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "" "https"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "https"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "https" "Path=/; SameSite=lax; HttpOnly; Secure;"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "rp.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "rp.company.com" "https://sso.company.com/oxauth/restv1/authorize"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "rp.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "rp.company.com" "hmac_key"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "/htvar/ugly.jsp"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "/htvar/ugly.jsp" "openid+profile+email+user_name+user_role+user_type"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "/htvar/ugly.jsp"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "/htvar/ugly.jsp" "client-id-aaa"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "https"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script copy: "://"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "rp.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script copy: ":"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "443"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "" "https://rp.company.com:443"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "rp.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "rp.company.com" "0"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http finalize request: 302, "/htvar/ugly.jsp?" a:1, c:3
2021/12/08 16:29:25 [debug] 21314#21314: *2 http special response: 302, "/htvar/ugly.jsp?"
2021/12/08 16:29:25 [debug] 21314#21314: *2 HTTP/1.1 302 Moved Temporarily
Server: nginx/1.21.3
Date: Wed, 08 Dec 2021 08:29:25 GMT
Content-Type: text/html
Content-Length: 145
Connection: keep-alive
WWW-Authenticate: Bearer realm=""
Set-Cookie: auth_redir=/htvar/ugly.jsp; Path=/; SameSite=lax; HttpOnly; Secure;
Set-Cookie: auth_nonce=85e6aa6169ae466048c5672482f4d03d; Path=/; SameSite=lax; HttpOnly; Secure;
Location: https://sso.company.com/oxauth/restv1/authorize?response_type=code&scope=openid+profile+email+user_name+user_role+user_type&client_id=client-id-aaa&redirect_uri=https://rp.company.com:443/_codexch&nonce=TfWwxHwliyU-T3kbxPrbc_FKqupcfcDlkuxdiLrCawA&state=0

2021/12/08 16:29:25 [debug] 21314#21314: *2 write new buf t:1 f:0 0000560F1504ED50, pos 0000560F1504ED50, size: 670 file: 0, size: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 http write filter: l:0 f:0 s:670
2021/12/08 16:29:25 [debug] 21314#21314: *2 http output filter "/htvar/ugly.jsp?"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http copy filter: "/htvar/ugly.jsp?"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http postpone filter "/htvar/ugly.jsp?" 0000560F1504F138
2021/12/08 16:29:25 [debug] 21314#21314: *2 write old buf t:1 f:0 0000560F1504ED50, pos 0000560F1504ED50, size: 670 file: 0, size: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 write new buf t:0 f:0 0000000000000000, pos 0000560F142A8820, size: 92 file: 0, size: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 write new buf t:0 f:0 0000000000000000, pos 0000560F142A8C00, size: 53 file: 0, size: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 http write filter: l:1 f:0 s:815
2021/12/08 16:29:25 [debug] 21314#21314: *2 http write filter limit 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 posix_memalign: 0000560F15052670:512 @16
2021/12/08 16:29:25 [debug] 21314#21314: *2 malloc: 0000560F15055110:16384
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL buf copy: 670
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL buf copy: 92
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL buf copy: 53
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL to write: 815
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_write: 815
2021/12/08 16:29:25 [debug] 21314#21314: *2 http write filter 0000000000000000
2021/12/08 16:29:25 [debug] 21314#21314: *2 http copy filter: 0 "/htvar/ugly.jsp?"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http finalize request: 0, "/htvar/ugly.jsp?" a:1, c:3
2021/12/08 16:29:25 [debug] 21314#21314: *2 http request count:3 blk:0
2021/12/08 16:29:25 [debug] 21314#21314: *2 http finalize request: -4, "/htvar/ugly.jsp?" a:1, c:2
2021/12/08 16:29:25 [debug] 21314#21314: *2 http request count:2 blk:0
2021/12/08 16:29:25 [debug] 21314#21314: *2 http finalize request: -4, "/htvar/ugly.jsp?" a:1, c:1
2021/12/08 16:29:25 [debug] 21314#21314: *2 set http keepalive handler
2021/12/08 16:29:25 [debug] 21314#21314: *2 http close request
2021/12/08 16:29:25 [debug] 21314#21314: *2 http log handler
2021/12/08 16:29:25 [debug] 21314#21314: *2 http session log handler
2021/12/08 16:29:25 [debug] 21314#21314: *2 run cleanup: 0000560F1504E9B0
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F14F12A60, unused: 3
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F1504E2C0, unused: 48
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F15052B80
2021/12/08 16:29:25 [debug] 21314#21314: *2 hc free: 0000000000000000
2021/12/08 16:29:25 [debug] 21314#21314: *2 hc busy: 0000000000000000 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F15055110
2021/12/08 16:29:25 [debug] 21314#21314: *2 reusable connection: 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 event timer add: 16: 65000:429936588
2021/12/08 16:29:25 [debug] 21314#21314: *2 http keepalive handler
2021/12/08 16:29:25 [debug] 21314#21314: *2 malloc: 0000560F15052B80:1024
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_read: 1024
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_read: avail:0
2021/12/08 16:29:25 [debug] 21314#21314: *2 reusable connection: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 posix_memalign: 0000560F14F12A60:4096 @16
2021/12/08 16:29:25 [debug] 21314#21314: *2 event timer del: 16: 429936588
2021/12/08 16:29:25 [debug] 21314#21314: *2 http process request line
2021/12/08 16:29:25 [debug] 21314#21314: *2 http request line: "GET /_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7 HTTP/1.1"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http uri: "/_codexch"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http args: "code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http exten: ""
2021/12/08 16:29:25 [debug] 21314#21314: *2 posix_memalign: 0000560F1504E2C0:4096 @16
2021/12/08 16:29:25 [debug] 21314#21314: *2 http process request header line
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Host: rp.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Connection: keep-alive"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "DNT: 1"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Upgrade-Insecure-Requests: 1"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36"
2021/12/08 16:29:25 [debug] 21314#21314: *2 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"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Sec-Fetch-Site: none"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Sec-Fetch-Mode: navigate"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Sec-Fetch-User: ?1"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Sec-Fetch-Dest: document"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "sec-ch-ua: " Not A;Brand";v="99", "Chromium";v="96", "Google Chrome";v="96""
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "sec-ch-ua-mobile: ?0"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "sec-ch-ua-platform: "Windows""
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Accept-Encoding: gzip, deflate, br"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Accept-Language: en-SG,en;q=0.9"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http alloc large header buffer
2021/12/08 16:29:25 [debug] 21314#21314: *2 malloc: 0000560F1504F2D0:8192
2021/12/08 16:29:25 [debug] 21314#21314: *2 http large header alloc: 0000560F1504F2D0 8192
2021/12/08 16:29:25 [debug] 21314#21314: *2 http large header copy: 78
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_read: 5
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_read: -1
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_get_error: 2
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header: "Cookie: auth_redir=/htvar/ugly.jsp; auth_nonce=85e6aa6169ae466048c5672482f4d03d"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http header done
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 rewrite phase: 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script value: "NGINX / OpenID Connect login failure
"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script set $internal_error_message
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script value: ""
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script set $pkce_id
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script value: "/_codexch"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script set $redir_location
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "/"
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "_refresh"
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "_jwks_uri"
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "_id_token_validation"
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "_codexch"
2021/12/08 16:29:25 [debug] 21314#21314: *2 using configuration "=/_codexch"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http cl:-1 max:1048576
2021/12/08 16:29:25 [debug] 21314#21314: *2 rewrite phase: 3
2021/12/08 16:29:25 [debug] 21314#21314: *2 post rewrite phase: 4
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 5
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 6
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 7
2021/12/08 16:29:25 [debug] 21314#21314: *2 access phase: 8
2021/12/08 16:29:25 [debug] 21314#21314: *2 access phase: 9
2021/12/08 16:29:25 [debug] 21314#21314: *2 access phase: 10
2021/12/08 16:29:25 [debug] 21314#21314: *2 access phase: 11
2021/12/08 16:29:25 [debug] 21314#21314: *2 post access phase: 12
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 13
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 14
2021/12/08 16:29:25 [debug] 21314#21314: *2 add cleanup: 0000560F1504E8D8
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "rp.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "rp.company.com" "0"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "/_codexch"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "/_codexch" "my-client-secret"
2021/12/08 16:29:25 [debug] 21314#21314: *2 posix_memalign: 0000560F15043910:4096 @16
2021/12/08 16:29:25 [debug] 21314#21314: *2 http subrequest "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http finalize request: -4, "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7" a:1, c:3
2021/12/08 16:29:25 [debug] 21314#21314: *2 http request count:3 blk:0
2021/12/08 16:29:25 [debug] 21314#21314: *2 http posted request: "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret"
2021/12/08 16:29:25 [debug] 21314#21314: *2 rewrite phase: 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script value: "NGINX / OpenID Connect login failure
"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script set $internal_error_message
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script value: ""
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script set $pkce_id
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script value: "/_codexch"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script set $redir_location
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "/"
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "_refresh"
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "htvar/"
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "api/"
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "_token"
2021/12/08 16:29:25 [debug] 21314#21314: *2 using configuration "=/_token"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http cl:-1 max:1048576
2021/12/08 16:29:25 [debug] 21314#21314: *2 rewrite phase: 3
2021/12/08 16:29:25 [debug] 21314#21314: *2 post rewrite phase: 4
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 5
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 6
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 7
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 13
2021/12/08 16:29:25 [debug] 21314#21314: *2 generic phase: 14
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "rp.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "rp.company.com" "https://sso.company.com/oxauth/restv1/token"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "https://sso.company.com/oxauth/restv1/token"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http init upstream, client timer: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 epoll add event: fd:16 op:3 ev:80002005
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "/_token"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "/_token" "my-client-id"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "https"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "" "https"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "https"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script copy: "://"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "rp.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script copy: ":"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "443"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "" "https://rp.company.com:443"
2021/12/08 16:29:25 [debug] 21314#21314: *2 posix_memalign: 0000560F15055110:4096 @16
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script copy: "Content-Type"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script copy: "application/x-www-form-urlencoded"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script copy: "Host"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "sso.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script copy: "Connection"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script copy: "close"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script copy: "Content-Length"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "175"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script copy: ""
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "DNT: 1"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "Upgrade-Insecure-Requests: 1"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36"
2021/12/08 16:29:25 [debug] 21314#21314: *2 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"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "Sec-Fetch-Site: none"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "Sec-Fetch-Mode: navigate"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "Sec-Fetch-User: ?1"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "Sec-Fetch-Dest: document"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "sec-ch-ua: " Not A;Brand";v="99", "Chromium";v="96", "Google Chrome";v="96""
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "sec-ch-ua-mobile: ?0"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "sec-ch-ua-platform: "Windows""
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "Accept-Encoding: gzip, deflate, br"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "Accept-Language: en-SG,en;q=0.9"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "Cookie: auth_redir=/htvar/ugly.jsp; auth_nonce=85e6aa6169ae466048c5672482f4d03d"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script copy: "grant_type=authorization_code&client_id="
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "my-client-id"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script copy: "&"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script copy: "&redirect_uri="
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "https://rp.company.com:443"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "/_codexch"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header:
"POST /oxauth/restv1/token HTTP/1.0
Content-Type: application/x-www-form-urlencoded
Host: sso.company.com
Connection: close
Content-Length: 175
DNT: 1
Upgrade-Insecure-Requests: 1
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36
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
Sec-Fetch-Site: none
Sec-Fetch-Mode: navigate
Sec-Fetch-User: ?1
Sec-Fetch-Dest: document
sec-ch-ua: " Not A;Brand";v="99", "Chromium";v="96", "Google Chrome";v="96"
sec-ch-ua-mobile: ?0
sec-ch-ua-platform: "Windows"
Accept-Encoding: gzip, deflate, br
Accept-Language: en-SG,en;q=0.9
Cookie: auth_redir=/htvar/ugly.jsp; auth_nonce=85e6aa6169ae466048c5672482f4d03d

grant_type=authorization_code&client_id=my-client-id&code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret&redirect_uri=https://rp.company.com:443/_codexch"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http cleanup add: 0000560F150445D0
2021/12/08 16:29:25 [debug] 21314#21314: *2 http finalize request: -4, "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret" a:0, c:3
2021/12/08 16:29:25 [debug] 21314#21314: *2 http request count:3 blk:0
2021/12/08 16:29:25 [debug] 21314#21314: *2 http run request: "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http output filter "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http copy filter: "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http postpone filter "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7" 0000000000000000
2021/12/08 16:29:25 [debug] 21314#21314: *2 http copy filter: 0 "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http upstream resolve: "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret"
2021/12/08 16:29:25 [debug] 21314#21314: *2 name was resolved to 192.168.0.168
2021/12/08 16:29:25 [debug] 21314#21314: *2 get rr peer, try: 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 stream socket 18
2021/12/08 16:29:25 [debug] 21314#21314: *2 epoll add connection: fd:18 ev:80002005
2021/12/08 16:29:25 [debug] 21314#21314: *2 connect to 192.168.0.168:443, fd:18 #4
2021/12/08 16:29:25 [debug] 21314#21314: *2 http upstream connect: -2
2021/12/08 16:29:25 [debug] 21314#21314: *2 posix_memalign: 0000560F14FD03F0:128 @16
2021/12/08 16:29:25 [debug] 21314#21314: *2 event timer add: 18: 60000:429931761
2021/12/08 16:29:25 [debug] 21314#21314: *2 http upstream request: "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http upstream send request handler
2021/12/08 16:29:25 [debug] 21314#21314: *2 malloc: 0000560F14F013A0:96
2021/12/08 16:29:25 [debug] 21314#21314: *2 upstream SSL server name: "sso.company.com"
2021/12/08 16:29:25 [debug] 21314#21314: *2 tcp_nodelay
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_do_handshake: -1
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_get_error: 2
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL handshake handler: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_do_handshake: -1
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_get_error: 2
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL handshake handler: 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_do_handshake: -1
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_get_error: 2
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL handshake handler: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_do_handshake: 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL: TLSv1.2, cipher: "ECDHE-RSA-AES256-GCM-SHA384 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(256) Mac=AEAD"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http upstream ssl handshake: "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http upstream send request
2021/12/08 16:29:25 [debug] 21314#21314: *2 http upstream send request body
2021/12/08 16:29:25 [debug] 21314#21314: *2 chain writer buf fl:1 s:1013
2021/12/08 16:29:25 [debug] 21314#21314: *2 chain writer in: 0000560F150448E8
2021/12/08 16:29:25 [debug] 21314#21314: *2 malloc: 0000560F1506AFF0:80
2021/12/08 16:29:25 [debug] 21314#21314: *2 malloc: 0000560F15056120:16384
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL buf copy: 1013
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL to write: 1013
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_write: 1013
2021/12/08 16:29:25 [debug] 21314#21314: *2 chain writer out: 0000000000000000
2021/12/08 16:29:25 [debug] 21314#21314: *2 event timer del: 18: 429931761
2021/12/08 16:29:25 [debug] 21314#21314: *2 event timer add: 18: 60000:429931768
2021/12/08 16:29:25 [debug] 21314#21314: *2 http upstream process header
2021/12/08 16:29:25 [debug] 21314#21314: *2 malloc: 0000560F1505A130:4096
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_read: -1
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_get_error: 2
2021/12/08 16:29:25 [debug] 21314#21314: *2 http upstream request: "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http upstream dummy handler
2021/12/08 16:29:25 [debug] 21314#21314: *2 http upstream request: "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http upstream process header
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_read: 343
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_read: 628
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_read: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_get_error: 5
2021/12/08 16:29:25 [debug] 21314#21314: *2 peer shutdown SSL cleanly
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy status 401 "401 Unauthorized"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "Date: Wed, 08 Dec 2021 08:29:25 GMT"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "Server: Apache"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "X-Xss-Protection: 1; mode=block"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "X-Content-Type-Options: nosniff"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "Strict-Transport-Security: max-age=31536000; includeSubDomains"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "WWW-Authenticate: Basic realm="oxAuth""
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "Content-Type: application/json;charset=iso-8859-1"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "Content-Length: 628"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header: "Connection: close"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header done
2021/12/08 16:29:25 [debug] 21314#21314: *2 http cacheable: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy filter init s:401 h:0 c:0 l:628
2021/12/08 16:29:25 [debug] 21314#21314: *2 http upstream process upstream
2021/12/08 16:29:25 [debug] 21314#21314: *2 pipe read upstream: 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 pipe preread: 628
2021/12/08 16:29:25 [debug] 21314#21314: *2 pipe recv chain: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 pipe buf free s:0 t:1 f:0 0000560F1505A130, pos 0000560F1505A287, size: 628 file: 0, size: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 pipe length: 628
2021/12/08 16:29:25 [debug] 21314#21314: *2 input buf #0
2021/12/08 16:29:25 [debug] 21314#21314: *2 pipe write downstream: 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 pipe write downstream flush in
2021/12/08 16:29:25 [debug] 21314#21314: *2 http output filter "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http copy filter: "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http postpone filter "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret" 0000560F15055BE8
2021/12/08 16:29:25 [debug] 21314#21314: *2 http postpone filter in memory
2021/12/08 16:29:25 [debug] 21314#21314: *2 http postpone filter in memory 628 bytes
2021/12/08 16:29:25 [debug] 21314#21314: *2 http copy filter: 0 "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret"
2021/12/08 16:29:25 [debug] 21314#21314: *2 pipe write downstream done
2021/12/08 16:29:25 [debug] 21314#21314: *2 event timer: 18, old: 429931768, new: 429931781
2021/12/08 16:29:25 [debug] 21314#21314: *2 http upstream exit: 0000000000000000
2021/12/08 16:29:25 [debug] 21314#21314: *2 finalize http upstream request: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 finalize http proxy request
2021/12/08 16:29:25 [debug] 21314#21314: *2 free rr peer 1 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_shutdown: 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 close http upstream connection: 18
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F15056120
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F1506AFF0
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F14F013A0
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F14FD03F0, unused: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 event timer del: 18: 429931768
2021/12/08 16:29:25 [debug] 21314#21314: *2 reusable connection: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 http upstream temp fd: -1
2021/12/08 16:29:25 [debug] 21314#21314: *2 http output filter "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http copy filter: "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http postpone filter "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret" 00007FFE9BFA0D60
2021/12/08 16:29:25 [debug] 21314#21314: *2 http postpone filter in memory
2021/12/08 16:29:25 [debug] 21314#21314: *2 http copy filter: 0 "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http finalize request: 0, "/_token?code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret" a:0, c:2
2021/12/08 16:29:25 [debug] 21314#21314: *2 posix_memalign: 0000560F15056120:4096 @16
2021/12/08 16:29:25 [error] 21314#21314: *2 js: OIDC error from IdP when sending authorization code: invalid_client, Client authentication failed (e.g. unknown client, no client authentication included, or unsupported authentication method). The authorization server MAY return an HTTP 401 (Unauthorized) status code to indicate which HTTP authentication schemes are supported. If the client attempted to authenticate via the Authorization request header field, the authorization server MUST respond with an HTTP 401 (Unauthorized) status code, and include the WWW-Authenticate response header field matching the authentication scheme used by the client.
2021/12/08 16:29:25 [debug] 21314#21314: *2 http request count:2 blk:0
2021/12/08 16:29:25 [debug] 21314#21314: *2 http posted request: "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http finalize request: 502, "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7" a:1, c:1
2021/12/08 16:29:25 [debug] 21314#21314: *2 http special response: 502, "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7"
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "@do_oidc_flow"
2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "@oidc_error"
2021/12/08 16:29:25 [debug] 21314#21314: *2 using location: @oidc_error "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7"
2021/12/08 16:29:25 [debug] 21314#21314: *2 rewrite phase: 3
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "NGINX / OpenID Connect login failure
"
2021/12/08 16:29:25 [debug] 21314#21314: *2 HTTP/1.1 502 Bad Gateway
Server: nginx/1.21.3
Date: Wed, 08 Dec 2021 08:29:25 GMT
Content-Type: text/plain
Content-Length: 37
Connection: keep-alive

2021/12/08 16:29:25 [debug] 21314#21314: *2 write new buf t:1 f:0 0000560F15056520, pos 0000560F15056520, size: 157 file: 0, size: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 http write filter: l:0 f:0 s:157
2021/12/08 16:29:25 [debug] 21314#21314: *2 http output filter "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http copy filter: "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http postpone filter "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7" 00007FFE9BFA0C50
2021/12/08 16:29:25 [debug] 21314#21314: *2 write old buf t:1 f:0 0000560F15056520, pos 0000560F15056520, size: 157 file: 0, size: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 write new buf t:0 f:0 0000000000000000, pos 0000560F15056458, size: 37 file: 0, size: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 http write filter: l:1 f:0 s:194
2021/12/08 16:29:25 [debug] 21314#21314: *2 http write filter limit 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 malloc: 0000560F15067830:16384
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL buf copy: 157
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL buf copy: 37
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL to write: 194
2021/12/08 16:29:25 [debug] 21314#21314: *2 SSL_write: 194
2021/12/08 16:29:25 [debug] 21314#21314: *2 http write filter 0000000000000000
2021/12/08 16:29:25 [debug] 21314#21314: *2 http copy filter: 0 "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http finalize request: 0, "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7" a:1, c:2
2021/12/08 16:29:25 [debug] 21314#21314: *2 http request count:2 blk:0
2021/12/08 16:29:25 [debug] 21314#21314: *2 http finalize request: -4, "/_codexch?code=b8bbd874-6eab-4282-b755-8501025ba68e&scope=user_role+user_type+openid+user_name+profile+email&session_id=31be09e0-b503-4928-9fa5-c2d706cdde4b&state=0&session_state=838d83a219f4e96aa1714452d1e6c5ff01c6cb12cfa69077f7e67b689f8c11bb.ac39bee8-bff6-4853-8d7c-18454f6f14f7" a:1, c:1
2021/12/08 16:29:25 [debug] 21314#21314: *2 set http keepalive handler
2021/12/08 16:29:25 [debug] 21314#21314: *2 http close request
2021/12/08 16:29:25 [debug] 21314#21314: *2 http log handler
2021/12/08 16:29:25 [debug] 21314#21314: *2 http session log handler
2021/12/08 16:29:25 [debug] 21314#21314: *2 run cleanup: 0000560F1504E8D8
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F1505A130
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F14F12A60, unused: 3
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F1504E2C0, unused: 4
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F15043910, unused: 8
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F15055110, unused: 0
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F15056120, unused: 2189
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F15052B80
2021/12/08 16:29:25 [debug] 21314#21314: *2 hc free: 0000000000000000
2021/12/08 16:29:25 [debug] 21314#21314: *2 hc busy: 0000560F15052740 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F1504F2D0
2021/12/08 16:29:25 [debug] 21314#21314: *2 free: 0000560F15067830
2021/12/08 16:29:25 [debug] 21314#21314: *2 reusable connection: 1
2021/12/08 16:29:25 [debug] 21314#21314: *2 event timer add: 16: 65000:429936781

Nginx Version

# nginx -V
nginx version: nginx/1.21.3 (nginx-plus-r25)
built by gcc 4.8.5 20150623 (Red Hat 4.8.5-44) (GCC)
built with OpenSSL 1.0.2k-fips  26 Jan 2017
TLS SNI support enabled
configure arguments: --prefix=/etc/nginx --sbin-path=/usr/sbin/nginx --modules-path=/usr/lib64/nginx/modules --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --pid-path=/var/run/nginx.pid --lock-path=/var/run/nginx.lock --http-client-body-temp-path=/var/cache/nginx/client_temp --http-proxy-temp-path=/var/cache/nginx/proxy_temp --http-fastcgi-temp-path=/var/cache/nginx/fastcgi_temp --http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp --http-scgi-temp-path=/var/cache/nginx/scgi_temp --user=nginx --group=nginx --with-compat --with-file-aio --with-threads --with-http_addition_module --with-http_auth_request_module --with-http_dav_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_realip_module --with-http_secure_link_module --with-http_slice_module --with-http_ssl_module --with-http_stub_status_module --with-http_sub_module --with-http_v2_module --with-mail --with-mail_ssl_module --with-stream --with-stream_realip_module --with-stream_ssl_module --with-stream_ssl_preread_module --build=nginx-plus-r25 --with-http_auth_jwt_module --with-http_f4f_module --with-http_hls_module --with-http_session_log_module --with-cc-opt='-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong --param=ssp-buffer-size=4 -grecord-gcc-switches -m64 -mtune=generic -DIP_BIND_ADDRESS_NO_PORT=24 -fPIC' --with-ld-opt='-Wl,-z,relro -Wl,-z,now -pie'

Any idea if I missed out on any any configuration for URI?
@tippexs tippexs added the question Further information is requested label Dec 8, 2021
@tippexs tippexs self-assigned this Dec 8, 2021
@lcrilly
Copy link
Contributor

lcrilly commented Dec 8, 2021

Here is the relevant line from the error log

2021/12/08 16:29:25 [error] 21314#21314: *2 js: OIDC error from IdP when sending authorization code: invalid_client, Client authentication failed (e.g. unknown client, no client authentication included, or unsupported authentication method). The authorization server MAY return an HTTP 401 (Unauthorized) status code to indicate which HTTP authentication schemes are supported. If the client attempted to authenticate via the Authorization request header field, the authorization server MUST respond with an HTTP 401 (Unauthorized) status code, and include the WWW-Authenticate response header field matching the authentication scheme used by the client.

Check your client authentication settings.

@wongkeewee
Copy link
Author

Hi @lcrilly,

Thank for the response

Yes, but from the request above, it is sending the wrong Client ID and Secret (the default Client ID and Secret wasn't sanitized in my logs, only the hostnames and actual Client ID/Secret) to my IDP

2021/12/08 16:29:25 [debug] 21314#21314: *2 http proxy header:
"POST /oxauth/restv1/token HTTP/1.0
Content-Type: application/x-www-form-urlencoded
Host: sso.company.com
Connection: close
Content-Length: 175
DNT: 1
Upgrade-Insecure-Requests: 1
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36
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
Sec-Fetch-Site: none
Sec-Fetch-Mode: navigate
Sec-Fetch-User: ?1
Sec-Fetch-Dest: document
sec-ch-ua: " Not A;Brand";v="99", "Chromium";v="96", "Google Chrome";v="96"
sec-ch-ua-mobile: ?0
sec-ch-ua-platform: "Windows"
Accept-Encoding: gzip, deflate, br
Accept-Language: en-SG,en;q=0.9
Cookie: auth_redir=/htvar/ugly.jsp; auth_nonce=85e6aa6169ae466048c5672482f4d03d

grant_type=authorization_code&client_id=my-client-id&code=b8bbd874-6eab-4282-b755-8501025ba68e&client_secret=my-client-secret&redirect_uri=https://rp.company.com:443/_codexch"

This seems to be from the default mappings

...
map $uri $oidc_client {
    ~^/htvar/(.*)$ client-id-aaa;

    default "my-client-id";
}


...

map $uri $oidc_client_secret {
    ~^/htvar/(.*)$ "client-secret-aaa";

    default "my-client-secret";
}
...

The logs on my IDP side is also showing the invalid client id

2021-12-08 16:29:25,964 DEBUG [qtp1590550415-6994] [org.gluu.oxauth.service.ClientService] (ClientService.java:136) - Found 0 entries for client id = my-client-id
2021-12-08 16:29:25,964 DEBUG [qtp1590550415-6994] [org.gluu.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:109) - Starting token endpoint authentication
2021-12-08 16:29:25,965 DEBUG [qtp1590550415-6994] [org.gluu.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:125) - Starting POST Auth token endpoint authentication
2021-12-08 16:29:25,965 DEBUG [qtp1590550415-6994] [org.gluu.oxauth.auth.AuthenticationFilter] (AuthenticationFilter.java:331) - requireAuth: 'true'
2021-12-08 16:29:25,967 DEBUG [qtp1590550415-6994] [org.gluu.oxauth.service.ClientService] (ClientService.java:136) - Found 0 entries for client id = my-client-id
2021-12-08 16:29:25,968 DEBUG [qtp1590550415-6994] [org.gluu.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:68) - Looking for the error with id: invalid_client
2021-12-08 16:29:25,968 DEBUG [qtp1590550415-6994] [org.gluu.oxauth.model.error.ErrorResponseFactory] (ErrorResponseFactory.java:73) - Found error, id: invalid_client

@tippexs tippexs added the enhancement New feature or request label Dec 10, 2021
@tippexs
Copy link
Contributor

tippexs commented Dec 10, 2021 •
edited

Hi @wongkeewee , thanks for reporting that issue in that detail! That definitely helped us to investigate the issue.

As the variable value assigned by a map will be assigned once the variable is used in the Nginx configuration (different from the set directive ) the oidc_client variable will be set correctly to your desired value client-id-aaa as the uri of your initial request is /htvar/ugly.jsp. BUT as soon as our OIDC implementation hits the _token location, due to an internal subrequest, the uri changes and the value will be reassigned to the default one. This can be tracked down in the logs as well:

Before the subrequest:

2021/12/08 16:29:25 [debug] 21314#21314: *2 http process request line
2021/12/08 16:29:25 [debug] 21314#21314: *2 http request line: "GET /htvar/ugly.jsp HTTP/1.1"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http uri: "/htvar/ugly.jsp"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http args: ""
2021/12/08 16:29:25 [debug] 21314#21314: *2 http exten: "jsp"
....
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "/htvar/ugly.jsp"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "/htvar/ugly.jsp" "client-id-aaa"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started

After the subrequest to _token

2021/12/08 16:29:25 [debug] 21314#21314: *2 test location: "_token"
2021/12/08 16:29:25 [debug] 21314#21314: *2 using configuration "=/_token"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http cl:-1 max:1048576
2021/12/08 16:29:25 [debug] 21314#21314: *2 rewrite phase: 3
2021/12/08 16:29:25 [debug] 21314#21314: *2 post rewrite phase: 4
....
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http script var: "/_token"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map: "/_token" "my-client-id"
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started
2021/12/08 16:29:25 [debug] 21314#21314: *2 http map started

As you can see, the value of your client-id had been changed as the value of uri had been changed as well.

I have created a small fix for this problem but need to test it or kindly ask you to give it a try. The solution is, we have to make sure the uri is kind of fixed to the value before the internal subrequest.

#js_var can hold variable values even over the boundaries of sub requests.
#presist the value of `uri` to make it available to the map in the subrequest.
js_var $ruri $uri;

map $ruri $oidc_client {
  /test "oidc-test-realm";
  /aaa "oidc-aaa-realm";
  default "oidc-default";
}

server {
 listen 9001;


 location / {
  js_content oidc.test;
 }

 location /_token {
   internal;
   return 200 $oidc_client;
 }


}

As you can see, I have just introduced another variable ruri set by js_var. Use the newly created variable ruri in the map. My test proved it will then use the original URI to lookup the map.

$ curl 127.1:9001/test

oidc-test-realm

Let me know if this works for you.
Cheers Timo

@tippexs tippexs mentioned this issue Dec 10, 2021
Closed
@wongkeewee
Copy link
Author

Hi @tippexs,

Thanks for the response!

Finally got a chance to test this out after the meltdown for past couple of days.

I've configured the js_var and $ruri in the openid_connect_configuration.conf file:

#js_var can hold variable values even over the boundaries of sub requests.
#presist the value of `uri` to make it available to the map in the subrequest.
js_var $ruri $uri;  
...
map $ruri $oidc_client {
    ~^/htvar/(.*)$ "client-id-aaa";

    default "my-client-id";
}

map $ruri $oidc_client_secret {
    ~^/htvar/(.*)$ "client-secret-aaa";

    default "my-client-secret";
}


map $ruri $oidc_scopes {
    ~^/htvar/(.*)$ "openid+profile+email+user_name+user_role+user_type";
    default "openid+profile+email+offline_access";
}

However, the _codexch is still throwing the same error and the IDP is still seeing my-client-id

Did I apply the configuration in the correct place, ie openid_connect_configuration.conf
Or is the $ruri variable overwritten everytime there is a new request and I should put the js_var $ruri $uri; line somewhere else?

@wongkeewee
Copy link
Author

Hi @tippexs,

I have configured the $ruri variable in our conf file, but the $ruri is still picking up the current URI and not mapping to the correct configuration.

Is there a specific location i need to place the js_var $ruri $uri; configuration?

@tippexs
Copy link
Contributor

tippexs commented Jan 18, 2022

The js_var $ruri $uri; can be set anywhere in the http context of your configuration. Can you please share the debug log one more time. If possible upload it to a GIST and share the link here. As debug logs can become quite large. Thanks

@wongkeewee
Copy link
Author

Hi @tippexs,

I have configured openid_connect_configuration.conf as follows:

# OpenID Connect configuration
#
# Each map block allows multiple values so that multiple IdPs can be supported,
# the $host variable is used as the default input parameter but can be changed.
#

#js_var can hold variable values even over the boundaries of sub requests.
#presist the value of `uri` to make it available to the map in the subrequest.
js_var $ruri $uri;

map $host $oidc_authz_endpoint {
    rp.minkhang.com https://gluu-ppl.azlabs.sg/oxauth/restv1/authorize;

    default "http://gluu-ppl.azlabs.sg/oxauth/restv1/authorize";
    #www.example.com "https://my-idp/oauth2/v1/authorize";
}

map $host $oidc_token_endpoint {
    rp.minkhang.com https://gluu-ppl.azlabs.sg/oxauth/restv1/token;

    default "https://gluu-ppl.azlabs.sg/oxauth/restv1/token";
}

map $host $oidc_jwt_keyfile {
    rp.minkhang.com https://gluu-ppl.azlabs.sg/oxauth/restv1/jwks;

    default "http://gluu-ppl.azlabs.sg/oxauth/restv1/jwks";
}

#map $host $oidc_client {
map $ruri $oidc_client {
    ~^/htvar/(.*)$ "client-id-aaa";
    #rp.minkhang.com "client-id-aaa";

    default "my-client-id";
}


map $host $oidc_pkce_enable {
    default 0;
}

#map $host $oidc_client_secret {
map $ruri $oidc_client_secret {
    ~^/htvar/(.*)$ "client-secret-aaa";
    #rp.minkhang.com "client-secret-aaa";

    default "my-client-secret";
}


#map $host $oidc_scopes {
map $ruri $oidc_scopes {
    ~^/htvar/(.*)$ "openid+profile+email+user_name+user_role+user_type";
    #rp.minkhang.com "openid+profile+email+user_name+user_role+user_type";
    default "openid+profile+email+offline_access";
}


map $host $oidc_logout_redirect {
    # Where to send browser after requesting /logout location. This can be
    # replaced with a custom logout page, or complete URL.
    rp.minkhang.com "https://gluu-ppl.azlabs.sg/oxauth/restv1/end_session?post_logout_redirect_uri=https%3A%2F%2Frp.minkhang.com%2Fhtvar%2F";
    default "/_logout"; # Built-in, simple logout page
}

map $host $oidc_hmac_key {
    rp.minkhang.com sV5IAum4OrMNpOs2rK4EfMLF;

    # This should be unique for every NGINX instance/cluster
    default "ChangeMe";
}

map $proto $oidc_cookie_flags {
    http  "Path=/; SameSite=lax;"; # For HTTP/plaintext testing
    https "Path=/; SameSite=lax; HttpOnly; Secure;"; # Production recommendation
}

map $http_x_forwarded_port $redirect_base {
    ""      $proto://$host:$server_port;
    default $proto://$host:$http_x_forwarded_port;
}

map $http_x_forwarded_proto $proto {
    ""      $scheme;
    default $http_x_forwarded_proto;
}

# ADVANCED CONFIGURATION BELOW THIS LINE
# Additional advanced configuration (server context) in openid_connect.server_conf

# JWK Set will be fetched from $oidc_jwks_uri and cached here - ensure writable by nginx user
proxy_cache_path /var/cache/nginx/jwk levels=1 keys_zone=jwk:64k max_size=1m;

# Change timeout values to at least the validity period of each token type
keyval_zone zone=oidc_id_tokens:1M state=conf.d/oidc_id_tokens.json timeout=1h;
keyval_zone zone=refresh_tokens:1M state=conf.d/refresh_tokens.json timeout=8h;
keyval_zone zone=oidc_pkce:128K timeout=90s; # Temporary storage for PKCE code verifier.

keyval $cookie_auth_token $session_jwt zone=oidc_id_tokens;   # Exchange cookie for JWT
keyval $cookie_auth_token $refresh_token zone=refresh_tokens; # Exchange cookie for refresh token
keyval $request_id $new_session zone=oidc_id_tokens; # For initial session creation
keyval $request_id $new_refresh zone=refresh_tokens; # ''
keyval $pkce_id $pkce_code_verifier zone=oidc_pkce;

auth_jwt_claim_set $jwt_audience aud; # In case aud is an array
js_import oidc from conf.d/openid_connect.js;

# vim: syntax=nginx

The debug logs are shared here https://drive.google.com/file/d/18g1K44cQeiAO50E4pOFsxBNl5v4rts7T/view?usp=sharing

It looks like the URI are not persisted across the OIDC call

2022/02/03 14:55:59 [debug] 19699#19699: *12 http map started
2022/02/03 14:55:59 [debug] 19699#19699: *12 http script var: "/_codexch"
2022/02/03 14:55:59 [debug] 19699#19699: *12 http script var: "/_codexch"
2022/02/03 14:55:59 [debug] 19699#19699: *12 http map: "/_codexch" "my-client-secret"

@wongkeewee
Copy link
Author

Hi @tippexs,

Are you able to advise based on the logs provided?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@tippexs tippexs

Labels
enhancement New feature or request question Further information is requested
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@tippexs @lcrilly @wongkeewee