From 1a0f9b50867fb5fa0cd2f05c543193c122b30d6e Mon Sep 17 00:00:00 2001 From: Mauro Mugnaini Date: Tue, 19 Jan 2021 15:04:31 +0100 Subject: [PATCH 1/4] A lot of logs added and rationalized loop --- .../SmartGearsPortalValve.java | 369 ++++++++++-------- 1 file changed, 203 insertions(+), 166 deletions(-) diff --git a/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java b/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java index 08171dc..ae2c1aa 100644 --- a/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java +++ b/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java @@ -33,8 +33,11 @@ import org.gcube.portal.oidc.lr62.LiferayOpenIdConnectConfiguration; import org.slf4j.Logger; import org.slf4j.LoggerFactory; +import com.liferay.portal.kernel.exception.PortalException; +import com.liferay.portal.kernel.exception.SystemException; import com.liferay.portal.model.User; import com.liferay.portal.service.UserLocalServiceUtil; +import com.liferay.portal.util.PortalUtil; /** * @@ -95,56 +98,177 @@ public class SmartGearsPortalValve extends ValveBase { private void checkUMATicket(HttpServletRequest request, HttpServletResponse response, String scope) { _log.debug("Getting current user"); User user = getCurrentUser(request); + User purUser = null; + try { + purUser = PortalUtil.getUser(request); + } catch (PortalException | SystemException e) { + _log.debug("Cannot get user via portal util: {}", e.getMessage()); + } if (user == null) { - // Almost impossible _log.error("Current user not found, cannot continue"); return; + } else { + _log.debug("Current user is: {} [{}]", user.getScreenName(), user.getEmailAddress()); + if (purUser != null) { + _log.debug("Current PURet user is: {} [{}]", purUser.getScreenName(), purUser.getEmailAddress()); + } else { + _log.debug("Current PURet user null"); + } } HttpSession session = request.getSession(false); if (session == null) { _log.debug("Session is null, cannot continue"); return; + } else { + _log.debug("Current session ID is {} and class instance is [{}]", session.getId(), + Integer.toHexString(session.hashCode())); } - synchronized (session) { - String urlEncodedScope = null; - try { - urlEncodedScope = URLEncoder.encode(scope, "UTF-8"); - } catch (UnsupportedEncodingException e) { - // Almost impossible - _log.error("Cannot URL encode scope", e); - return; - } - _log.debug("URL encoded scope is: {}", urlEncodedScope); + String urlEncodedScope = null; + try { + urlEncodedScope = URLEncoder.encode(scope, "UTF-8"); + } catch (UnsupportedEncodingException e) { + // Almost impossible + _log.error("Cannot URL encode scope", e); + return; + } + _log.debug("URL encoded scope is: {}", urlEncodedScope); + + _log.trace("Getting UMA token from session {} [{}]", session.getId(), Integer.toHexString(session.hashCode())); + JWTToken umaToken = JWTTokenUtil.getUMAFromSession(session); + if (umaToken == null) { + _log.debug("UMA token not found in session. Trying to get it from cache proxy"); + umaToken = JWTCacheProxy.getInstance().getUMAToken(user, session); + } + if (umaToken != null && !umaToken.isExpired() && umaToken.getAud().contains(urlEncodedScope)) { + _log.trace("Current UMA token is OK [{}]", umaToken.getTokenEssentials()); + if (JWTTokenUtil.getUMAFromSession(session) == null) { + _log.debug("Setting UMA token also in current session {} [{}]", session.getId(), + Integer.toHexString(session.hashCode())); - _log.trace("Getting UMA token from session: {}", session); - JWTToken umaToken = JWTTokenUtil.getUMAFromSession(session); - if (umaToken == null) { - _log.debug("UMA token not found in session. Trying to get it from cache proxy"); - umaToken = JWTCacheProxy.getInstance().getUMAToken(user, session); - } - if (umaToken != null && !umaToken.isExpired() && umaToken.getAud().contains(urlEncodedScope)) { - _log.trace("Current UMA token is OK"); - if (JWTTokenUtil.getUMAFromSession(session) == null) { - _log.debug("Setting UMA token also in current session"); - JWTTokenUtil.putUMAInSession(umaToken, session); - } - } else if (JWTCacheProxy.getInstance().getUMAToken(user, session) != null - && !JWTCacheProxy.getInstance().getUMAToken(user, session).isExpired() - && JWTCacheProxy.getInstance().getUMAToken(user, session).getAud().contains(urlEncodedScope)) { - - _log.debug("Cache proxy already contains the suitable UMA token. Putting it also in session and using it"); - umaToken = JWTCacheProxy.getInstance().getUMAToken(user, session); JWTTokenUtil.putUMAInSession(umaToken, session); - } else { - if (umaToken != null && umaToken.getAud().contains(urlEncodedScope) && umaToken.isExpired()) { - _log.debug("UMA token is expired, trying to refresh it"); - OpenIdConnectConfiguration configuration = LiferayOpenIdConnectConfiguration.getConfiguration(request); + } + } else if (JWTCacheProxy.getInstance().getUMAToken(user, session) != null + && !JWTCacheProxy.getInstance().getUMAToken(user, session).isExpired() + && JWTCacheProxy.getInstance().getUMAToken(user, session).getAud().contains(urlEncodedScope)) { + + _log.debug("Cache proxy already contains the suitable UMA token: {}", umaToken.getTokenEssentials()); + _log.debug("Putting it also in session {} [{}] and using it", session.getId(), + Integer.toHexString(session.hashCode())); + + umaToken = JWTCacheProxy.getInstance().getUMAToken(user, session); + JWTTokenUtil.putUMAInSession(umaToken, session); + } else { + if (umaToken != null && umaToken.getAud().contains(urlEncodedScope) && umaToken.isExpired()) { + _log.debug("UMA token is expired, trying to refresh it [{}]", umaToken.getTokenEssentials()); + OpenIdConnectConfiguration configuration = LiferayOpenIdConnectConfiguration + .getConfiguration(request); + try { + umaToken = OpenIdConnectRESTHelper.refreshToken(configuration.getTokenURL(), umaToken); + _log.debug("Setting refreshed UMA token in cache proxy [{}]", umaToken.getTokenEssentials()); + JWTCacheProxy.getInstance().setUMAToken(getCurrentUser(request), session, umaToken); + _log.debug("Setting refreshed UMA token in session {} [{}]", session.getId(), + Integer.toHexString(session.hashCode())); + + JWTTokenUtil.putUMAInSession(umaToken, session); + } catch (OpenIdConnectRESTHelperException e) { + if (e.hasJSONPayload()) { + if (OpenIdConnectRESTHelper.isInvalidBearerTokenError(e.getResponseString())) { + if (FORCE_LOGOUT_ON_INVALID_OIDC) { + _log.warn("OIDC token is become invalid, forcing redirect to logout URI"); + forceLogout(session, response); + } else { + _log.warn("OIDC token is become invalid, cannot continue"); + } + return; + } else if (OpenIdConnectRESTHelper.isTokenNotActiveError(e.getResponseString())) { + _log.info("UMA token is no more active, get new one"); + } + } else { + _log.error("Refreshing UMA token on server [" + umaToken.getTokenEssentials() + "]", e); + } + umaToken = null; + _log.info("Removing probably inactive OIDC token from session {} [{}}", session.getId(), + Integer.toHexString(session.hashCode())); + + JWTTokenUtil.removeOIDCFromSession(session); + _log.info("Removing all inactive UMA token from session {} [{}] and from cache proxy if present", + session.getId(), Integer.toHexString(session.hashCode())); + + JWTTokenUtil.removeUMAFromSession(session); + JWTCacheProxy.getInstance().removeUMAToken(user, session); + } + } + if (umaToken == null || !umaToken.getAud().contains(urlEncodedScope)) { + boolean scopeIsChanged = false; + if (umaToken == null) { + _log.debug("Getting new UMA token for scope {}", urlEncodedScope); + } else if (!umaToken.getAud().contains(urlEncodedScope)) { + scopeIsChanged = true; + _log.info("Getting new UMA for scope {} since it has been issued for another scope [{}]", + urlEncodedScope, umaToken.getTokenEssentials()); + } + _log.debug("Getting OIDC token from session {} [{}]", session.getId(), + Integer.toHexString(session.hashCode())); + + JWTToken authToken = JWTTokenUtil.getOIDCFromSession(session); + if (authToken == null) { + _log.debug("OIDC token not found in session. Trying to get it from cache proxy"); + authToken = JWTCacheProxy.getInstance().getOIDCToken(user, session); + if (authToken == null) { + _log.info("OIDC token is null also in cache proxy"); + if (FORCE_LOGOUT_ON_MISSING_OIDC) { + _log.warn("OIDC token is null also in cache proxy, force redirecting to logut URI"); + forceLogout(session, response); + } else { + _log.error("OIDC token is null also in cache proxy, cannot continue!"); + } + return; + } else { + _log.debug("Setting OIDC token took from cache proxy in session {} [{}}", session.getId(), + Integer.toHexString(session.hashCode())); + + JWTTokenUtil.putOIDCInSession(authToken, session); + } + } + OpenIdConnectConfiguration configuration = LiferayOpenIdConnectConfiguration.getConfiguration(request); + boolean isNotAuthorized = false; + int authorizationAttempts = 0; + do { try { - umaToken = OpenIdConnectRESTHelper.refreshToken(configuration.getTokenURL(), umaToken); - _log.debug("Setting refreshed UMA token in cache proxy"); - JWTCacheProxy.getInstance().setUMAToken(getCurrentUser(request), session, umaToken); - _log.debug("Setting refreshed UMA token in session"); - JWTTokenUtil.putUMAInSession(umaToken, session); + if (isNotAuthorized || scopeIsChanged || authToken.isExpired()) { + if (isNotAuthorized) { + _log.info( + "UMA token is not authorized with current OIDC token, " + + "refreshing it to be sure that new grants are present. " + + "[attempts: {}]", + authorizationAttempts); + } else if (scopeIsChanged) { + _log.info( + "Scope is changed, refreshing token to be sure that new grants are present"); + } else if (authToken.isExpired()) { + _log.debug("OIDC token is expired, trying to refresh it [{}]", + authToken.getTokenEssentials()); + } + try { + authToken = OpenIdConnectRESTHelper.refreshToken(configuration.getTokenURL(), + authToken); + } catch (OpenIdConnectRESTHelperException e) { + if (FORCE_LOGOUT_ON_OIDC_REFRESH_ERROR) { + _log.warn("Error refreshing OIDC token, force redirecting to logut URI"); + forceLogout(session, response); + } else { + _log.error("Refreshing OIDC token on server", e); + } + return; + } + _log.debug("Setting refreshed OIDC token in cache proxy and session"); + JWTCacheProxy.getInstance().setOIDCToken(user, session, authToken); + JWTTokenUtil.putOIDCInSession(authToken, session); + } + _log.info("Getting UMA token from OIDC endpoint for scope: " + urlEncodedScope); + umaToken = OpenIdConnectRESTHelper.queryUMAToken(configuration.getTokenURL(), + authToken.getAccessTokenAsBearer(), urlEncodedScope, null); + } catch (OpenIdConnectRESTHelperException e) { if (e.hasJSONPayload()) { if (OpenIdConnectRESTHelper.isInvalidBearerTokenError(e.getResponseString())) { @@ -152,142 +276,55 @@ public class SmartGearsPortalValve extends ValveBase { _log.warn("OIDC token is become invalid, forcing redirect to logout URI"); forceLogout(session, response); } else { - _log.warn("OIDC token is become invalid, cannot continue"); + _log.error("OIDC token is become invalid, cannot continue"); } return; - } else if (OpenIdConnectRESTHelper.isTokenNotActiveError(e.getResponseString())) { - _log.info("UMA token is no more active, get new one"); - } - } else { - _log.error("Refreshing UMA token on server", e); - } - umaToken = null; - _log.info("Removing probably inactive OIDC token from session"); - JWTTokenUtil.removeOIDCFromSession(session); - _log.info("Removing all inactive UMA token from session and from cache proxy if present"); - JWTTokenUtil.removeUMAFromSession(session); - JWTCacheProxy.getInstance().removeUMAToken(user, session); - } - } - if (umaToken == null || !umaToken.getAud().contains(urlEncodedScope)) { - boolean scopeIsChanged = false; - if (umaToken == null) { - _log.debug("Getting new UMA token for scope {}", urlEncodedScope); - } else if (!umaToken.getAud().contains(urlEncodedScope)) { - scopeIsChanged = true; - _log.info("UMA token has been issued for another scope ({}). Getting new one for scope: {}", - umaToken.getAud(), urlEncodedScope); - } - _log.debug("Getting OIDC token from session"); - JWTToken authToken = JWTTokenUtil.getOIDCFromSession(session); - if (authToken == null) { - _log.debug("OIDC token not found in session. Trying to get it from cache proxy"); - authToken = JWTCacheProxy.getInstance().getOIDCToken(user, session); - if (authToken == null) { - _log.info("OIDC token is null also in cache proxy"); - if (FORCE_LOGOUT_ON_MISSING_OIDC) { - _log.warn("OIDC token is null also in cache proxy, force redirecting to logut URI"); - forceLogout(session, response); - return; - } else { - _log.error("OIDC token is null also in cache proxy, cannot continue!"); - return; - } - } else { - _log.debug("Setting OIDC token took from cache proxy in session"); - JWTTokenUtil.putOIDCInSession(authToken, session); - } - } - OpenIdConnectConfiguration configuration = LiferayOpenIdConnectConfiguration.getConfiguration(request); - boolean OK = false; - boolean isNotAuthorized = false; - int authorizationAttempts = 0; - while (!OK) { - try { - if (isNotAuthorized || scopeIsChanged || authToken.isExpired()) { - if (isNotAuthorized) { - _log.info( - "UMA token is not authorized with current OIDC token, " - + "refreshing it to be sure that new grants are present. " - + "[attempts: {}]", - authorizationAttempts); - } else if (scopeIsChanged) { - _log.info("Scope is changed, refreshing token to be sure that new grants are present"); - } else if (authToken.isExpired()) { - _log.debug("OIDC token is expired, trying to refresh it"); - } - try { - authToken = OpenIdConnectRESTHelper.refreshToken(configuration.getTokenURL(), - authToken); - } catch (OpenIdConnectRESTHelperException e) { - if (FORCE_LOGOUT_ON_OIDC_REFRESH_ERROR) { - _log.warn("Error refreshing OIDC token, force redirecting to logut URI"); - forceLogout(session, response); - } else { - _log.error("Refreshing OIDC token on server", e); - } - return; - } - _log.debug("Setting refreshed OIDC token in cache proxy and session"); - JWTCacheProxy.getInstance().setOIDCToken(user, session, authToken); - JWTTokenUtil.putOIDCInSession(authToken, session); - } - _log.info("Getting UMA token from OIDC endpoint for scope: " + urlEncodedScope); - umaToken = OpenIdConnectRESTHelper.queryUMAToken(configuration.getTokenURL(), - authToken.getAccessTokenAsBearer(), urlEncodedScope, null); - - OK = true; - } catch (OpenIdConnectRESTHelperException e) { - if (e.hasJSONPayload()) { - if (OpenIdConnectRESTHelper.isInvalidBearerTokenError(e.getResponseString())) { - if (FORCE_LOGOUT_ON_INVALID_OIDC) { - _log.warn("OIDC token is become invalid, forcing redirect to logout URI"); - forceLogout(session, response); - } else { - _log.error("OIDC token is become invalid, cannot continue"); - } - return; - } else if (OpenIdConnectRESTHelper - .isAccessDeniedNotAuthorizedError(e.getResponseString())) { - _log.info("UMA token is" + (isNotAuthorized ? " still" : "") - + " not authorized with actual OIDC token"); - - isNotAuthorized = true; - authorizationAttempts += 1; - if (authorizationAttempts <= MAX_AUTHORIZATION_RETRY_ATTEMPTS) { - _log.debug("Sleeping " + AUTHORIZATION_RETRY_ATTEMPTS_DELAY - + " ms and refreshing the OIDC"); - try { - Thread.sleep(AUTHORIZATION_RETRY_ATTEMPTS_DELAY); - } catch (InterruptedException ie) { - ie.printStackTrace(); - } - } else { - _log.warn("OIDC token refresh attempts exhausted"); - return; - } - } - } else { - _log.error("Getting UMA token from server", e); - return; - } - } - } - } - _log.debug("Setting UMA token in cache proxy and in session"); - JWTCacheProxy.getInstance().setUMAToken(user, session, umaToken); - JWTTokenUtil.putUMAInSession(umaToken, session); - } - _log.trace("Current UMA token audience is: {}", umaToken.getAud()); + } else if (OpenIdConnectRESTHelper + .isAccessDeniedNotAuthorizedError(e.getResponseString())) { + _log.info("UMA token is" + (isNotAuthorized ? " still" : "") + + " not authorized with actual OIDC token"); - _log.debug("Setting UMA token in UMA JWT provider"); - UmaJWTProvider.instance.set(umaToken.getRaw()); + isNotAuthorized = true; + authorizationAttempts += 1; + if (authorizationAttempts <= MAX_AUTHORIZATION_RETRY_ATTEMPTS) { + _log.debug("Sleeping " + AUTHORIZATION_RETRY_ATTEMPTS_DELAY + + " ms and refreshing the OIDC"); + try { + Thread.sleep(AUTHORIZATION_RETRY_ATTEMPTS_DELAY); + } catch (InterruptedException ie) { + ie.printStackTrace(); + } + } else { + _log.warn("OIDC token refresh attempts exhausted"); + return; + } + } + } else { + _log.error("Getting UMA token from server", e); + return; + } + } + } while (isNotAuthorized); + } + _log.debug("Setting UMA token in cache proxy and in session {} [{}]", session.getId(), + Integer.toHexString(session.hashCode())); + + JWTCacheProxy.getInstance().setUMAToken(user, session, umaToken); + JWTTokenUtil.putUMAInSession(umaToken, session); } + _log.trace("Current UMA token in use is: {}", umaToken.getTokenEssentials()); + + _log.debug("Setting UMA token in UMA JWT provider"); + UmaJWTProvider.instance.set(umaToken.getRaw()); } protected void forceLogout(HttpSession session, HttpServletResponse response) { try { - response.sendRedirect(LOGOUT_URI); + if (!response.isCommitted()) { + response.sendRedirect(LOGOUT_URI); + } else { + _log.warn("Cannot redirect to logout URI since the response is already commited"); + } } catch (IOException e) { _log.error("Cannot redirect to logout URI: " + LOGOUT_URI, e); } From fc18dda68e8915f8372c059a67b272d82ba07adf Mon Sep 17 00:00:00 2001 From: Mauro Mugnaini Date: Tue, 19 Jan 2021 17:54:06 +0100 Subject: [PATCH 2/4] Remove the user of the session to store objects and rely on cache proxy only adding a mutex to avoid concurrency problems --- .../SmartGearsPortalValve.java | 320 ++++++++---------- 1 file changed, 139 insertions(+), 181 deletions(-) diff --git a/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java b/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java index ae2c1aa..834e1aa 100644 --- a/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java +++ b/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java @@ -28,7 +28,6 @@ import org.gcube.oidc.rest.OpenIdConnectConfiguration; import org.gcube.oidc.rest.OpenIdConnectRESTHelper; import org.gcube.oidc.rest.OpenIdConnectRESTHelperException; import org.gcube.portal.oidc.lr62.JWTCacheProxy; -import org.gcube.portal.oidc.lr62.JWTTokenUtil; import org.gcube.portal.oidc.lr62.LiferayOpenIdConnectConfiguration; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -115,202 +114,161 @@ public class SmartGearsPortalValve extends ValveBase { _log.debug("Current PURet user null"); } } - HttpSession session = request.getSession(false); - if (session == null) { - _log.debug("Session is null, cannot continue"); - return; - } else { - _log.debug("Current session ID is {} and class instance is [{}]", session.getId(), - Integer.toHexString(session.hashCode())); - } - String urlEncodedScope = null; - try { - urlEncodedScope = URLEncoder.encode(scope, "UTF-8"); - } catch (UnsupportedEncodingException e) { - // Almost impossible - _log.error("Cannot URL encode scope", e); - return; - } - _log.debug("URL encoded scope is: {}", urlEncodedScope); - - _log.trace("Getting UMA token from session {} [{}]", session.getId(), Integer.toHexString(session.hashCode())); - JWTToken umaToken = JWTTokenUtil.getUMAFromSession(session); - if (umaToken == null) { - _log.debug("UMA token not found in session. Trying to get it from cache proxy"); - umaToken = JWTCacheProxy.getInstance().getUMAToken(user, session); - } - if (umaToken != null && !umaToken.isExpired() && umaToken.getAud().contains(urlEncodedScope)) { - _log.trace("Current UMA token is OK [{}]", umaToken.getTokenEssentials()); - if (JWTTokenUtil.getUMAFromSession(session) == null) { - _log.debug("Setting UMA token also in current session {} [{}]", session.getId(), - Integer.toHexString(session.hashCode())); - - JWTTokenUtil.putUMAInSession(umaToken, session); + JWTToken umaToken = null; + synchronized (JWTCacheProxy.getInstance().getMutexFor(user)) { + HttpSession session = request.getSession(false); + if (session == null) { + _log.debug("Session is null, cannot continue"); + return; } - } else if (JWTCacheProxy.getInstance().getUMAToken(user, session) != null - && !JWTCacheProxy.getInstance().getUMAToken(user, session).isExpired() - && JWTCacheProxy.getInstance().getUMAToken(user, session).getAud().contains(urlEncodedScope)) { - - _log.debug("Cache proxy already contains the suitable UMA token: {}", umaToken.getTokenEssentials()); - _log.debug("Putting it also in session {} [{}] and using it", session.getId(), - Integer.toHexString(session.hashCode())); - - umaToken = JWTCacheProxy.getInstance().getUMAToken(user, session); - JWTTokenUtil.putUMAInSession(umaToken, session); - } else { - if (umaToken != null && umaToken.getAud().contains(urlEncodedScope) && umaToken.isExpired()) { - _log.debug("UMA token is expired, trying to refresh it [{}]", umaToken.getTokenEssentials()); - OpenIdConnectConfiguration configuration = LiferayOpenIdConnectConfiguration - .getConfiguration(request); - try { - umaToken = OpenIdConnectRESTHelper.refreshToken(configuration.getTokenURL(), umaToken); - _log.debug("Setting refreshed UMA token in cache proxy [{}]", umaToken.getTokenEssentials()); - JWTCacheProxy.getInstance().setUMAToken(getCurrentUser(request), session, umaToken); - _log.debug("Setting refreshed UMA token in session {} [{}]", session.getId(), - Integer.toHexString(session.hashCode())); - - JWTTokenUtil.putUMAInSession(umaToken, session); - } catch (OpenIdConnectRESTHelperException e) { - if (e.hasJSONPayload()) { - if (OpenIdConnectRESTHelper.isInvalidBearerTokenError(e.getResponseString())) { - if (FORCE_LOGOUT_ON_INVALID_OIDC) { - _log.warn("OIDC token is become invalid, forcing redirect to logout URI"); - forceLogout(session, response); - } else { - _log.warn("OIDC token is become invalid, cannot continue"); - } - return; - } else if (OpenIdConnectRESTHelper.isTokenNotActiveError(e.getResponseString())) { - _log.info("UMA token is no more active, get new one"); - } - } else { - _log.error("Refreshing UMA token on server [" + umaToken.getTokenEssentials() + "]", e); - } - umaToken = null; - _log.info("Removing probably inactive OIDC token from session {} [{}}", session.getId(), - Integer.toHexString(session.hashCode())); - - JWTTokenUtil.removeOIDCFromSession(session); - _log.info("Removing all inactive UMA token from session {} [{}] and from cache proxy if present", - session.getId(), Integer.toHexString(session.hashCode())); - - JWTTokenUtil.removeUMAFromSession(session); - JWTCacheProxy.getInstance().removeUMAToken(user, session); - } + String sessionId = session.getId(); + _log.debug("Current session ID is {}", sessionId); + String urlEncodedScope = null; + try { + urlEncodedScope = URLEncoder.encode(scope, "UTF-8"); + } catch (UnsupportedEncodingException e) { + // Almost impossible + _log.error("Cannot URL encode scope", e); + return; } - if (umaToken == null || !umaToken.getAud().contains(urlEncodedScope)) { - boolean scopeIsChanged = false; - if (umaToken == null) { - _log.debug("Getting new UMA token for scope {}", urlEncodedScope); - } else if (!umaToken.getAud().contains(urlEncodedScope)) { - scopeIsChanged = true; - _log.info("Getting new UMA for scope {} since it has been issued for another scope [{}]", - urlEncodedScope, umaToken.getTokenEssentials()); - } - _log.debug("Getting OIDC token from session {} [{}]", session.getId(), - Integer.toHexString(session.hashCode())); + _log.debug("URL encoded scope is: {}", urlEncodedScope); - JWTToken authToken = JWTTokenUtil.getOIDCFromSession(session); - if (authToken == null) { - _log.debug("OIDC token not found in session. Trying to get it from cache proxy"); - authToken = JWTCacheProxy.getInstance().getOIDCToken(user, session); - if (authToken == null) { - _log.info("OIDC token is null also in cache proxy"); - if (FORCE_LOGOUT_ON_MISSING_OIDC) { - _log.warn("OIDC token is null also in cache proxy, force redirecting to logut URI"); - forceLogout(session, response); - } else { - _log.error("OIDC token is null also in cache proxy, cannot continue!"); - } - return; - } else { - _log.debug("Setting OIDC token took from cache proxy in session {} [{}}", session.getId(), - Integer.toHexString(session.hashCode())); - - JWTTokenUtil.putOIDCInSession(authToken, session); - } - } - OpenIdConnectConfiguration configuration = LiferayOpenIdConnectConfiguration.getConfiguration(request); - boolean isNotAuthorized = false; - int authorizationAttempts = 0; - do { + _log.trace("Getting UMA token for session {}", sessionId); + umaToken = JWTCacheProxy.getInstance().getUMAToken(user, sessionId); + if (umaToken != null && !umaToken.isExpired() && umaToken.getAud().contains(urlEncodedScope)) { + _log.trace("Current UMA token is OK [{}]", umaToken.getTokenEssentials()); + } else { + if (umaToken != null && umaToken.getAud().contains(urlEncodedScope) && umaToken.isExpired()) { + _log.debug("UMA token is expired, trying to refresh it [{}]", umaToken.getTokenEssentials()); + OpenIdConnectConfiguration configuration = LiferayOpenIdConnectConfiguration + .getConfiguration(request); try { - if (isNotAuthorized || scopeIsChanged || authToken.isExpired()) { - if (isNotAuthorized) { - _log.info( - "UMA token is not authorized with current OIDC token, " - + "refreshing it to be sure that new grants are present. " - + "[attempts: {}]", - authorizationAttempts); - } else if (scopeIsChanged) { - _log.info( - "Scope is changed, refreshing token to be sure that new grants are present"); - } else if (authToken.isExpired()) { - _log.debug("OIDC token is expired, trying to refresh it [{}]", - authToken.getTokenEssentials()); - } - try { - authToken = OpenIdConnectRESTHelper.refreshToken(configuration.getTokenURL(), - authToken); - } catch (OpenIdConnectRESTHelperException e) { - if (FORCE_LOGOUT_ON_OIDC_REFRESH_ERROR) { - _log.warn("Error refreshing OIDC token, force redirecting to logut URI"); - forceLogout(session, response); - } else { - _log.error("Refreshing OIDC token on server", e); - } - return; - } - _log.debug("Setting refreshed OIDC token in cache proxy and session"); - JWTCacheProxy.getInstance().setOIDCToken(user, session, authToken); - JWTTokenUtil.putOIDCInSession(authToken, session); - } - _log.info("Getting UMA token from OIDC endpoint for scope: " + urlEncodedScope); - umaToken = OpenIdConnectRESTHelper.queryUMAToken(configuration.getTokenURL(), - authToken.getAccessTokenAsBearer(), urlEncodedScope, null); - + umaToken = OpenIdConnectRESTHelper.refreshToken(configuration.getTokenURL(), umaToken); + _log.debug("Setting refreshed UMA token in cache proxy [{}]", umaToken.getTokenEssentials()); + JWTCacheProxy.getInstance().setUMAToken(user, sessionId, umaToken); } catch (OpenIdConnectRESTHelperException e) { if (e.hasJSONPayload()) { if (OpenIdConnectRESTHelper.isInvalidBearerTokenError(e.getResponseString())) { if (FORCE_LOGOUT_ON_INVALID_OIDC) { _log.warn("OIDC token is become invalid, forcing redirect to logout URI"); - forceLogout(session, response); + forceLogout(response); } else { - _log.error("OIDC token is become invalid, cannot continue"); + _log.warn("OIDC token is become invalid, cannot continue"); } return; - } else if (OpenIdConnectRESTHelper - .isAccessDeniedNotAuthorizedError(e.getResponseString())) { - _log.info("UMA token is" + (isNotAuthorized ? " still" : "") - + " not authorized with actual OIDC token"); - - isNotAuthorized = true; - authorizationAttempts += 1; - if (authorizationAttempts <= MAX_AUTHORIZATION_RETRY_ATTEMPTS) { - _log.debug("Sleeping " + AUTHORIZATION_RETRY_ATTEMPTS_DELAY - + " ms and refreshing the OIDC"); - try { - Thread.sleep(AUTHORIZATION_RETRY_ATTEMPTS_DELAY); - } catch (InterruptedException ie) { - ie.printStackTrace(); - } - } else { - _log.warn("OIDC token refresh attempts exhausted"); - return; - } + } else if (OpenIdConnectRESTHelper.isTokenNotActiveError(e.getResponseString())) { + _log.info("UMA token is no more active, get new one"); } } else { - _log.error("Getting UMA token from server", e); - return; + _log.error("Refreshing UMA token on server [" + umaToken.getTokenEssentials() + "]", e); } + umaToken = null; + _log.info("Removing inactive UMA token from cache proxy if present"); + JWTCacheProxy.getInstance().removeUMAToken(user, sessionId); } - } while (isNotAuthorized); - } - _log.debug("Setting UMA token in cache proxy and in session {} [{}]", session.getId(), - Integer.toHexString(session.hashCode())); + } + if (umaToken == null || !umaToken.getAud().contains(urlEncodedScope)) { + boolean scopeIsChanged = false; + if (umaToken == null) { + _log.debug("Getting new UMA token for scope {}", urlEncodedScope); + } else if (!umaToken.getAud().contains(urlEncodedScope)) { + scopeIsChanged = true; + _log.info("Getting new UMA for scope {} since it has been issued for another scope [{}]", + urlEncodedScope, umaToken.getTokenEssentials()); + } + _log.debug("Getting OIDC token from cache proxy"); - JWTCacheProxy.getInstance().setUMAToken(user, session, umaToken); - JWTTokenUtil.putUMAInSession(umaToken, session); + JWTToken authToken = JWTCacheProxy.getInstance().getOIDCToken(user, sessionId); + if (authToken == null) { + _log.info("OIDC token is null also in cache proxy"); + if (FORCE_LOGOUT_ON_MISSING_OIDC) { + _log.warn("OIDC token is null also in cache proxy, force redirecting to logut URI"); + forceLogout(response); + } else { + _log.error("OIDC token is null also in cache proxy, cannot continue!"); + } + return; + } + OpenIdConnectConfiguration configuration = LiferayOpenIdConnectConfiguration + .getConfiguration(request); + boolean isNotAuthorized = false; + int authorizationAttempts = 0; + do { + try { + if (isNotAuthorized || scopeIsChanged || authToken.isExpired()) { + if (isNotAuthorized) { + _log.info( + "UMA token is not authorized with current OIDC token, " + + "refreshing it to be sure that new grants are present. " + + "[attempts: {}]", + authorizationAttempts); + } else if (scopeIsChanged) { + _log.info( + "Scope is changed, refreshing token to be sure that new grants are present"); + } else if (authToken.isExpired()) { + _log.debug("OIDC token is expired, trying to refresh it [{}]", + authToken.getTokenEssentials()); + } + try { + authToken = OpenIdConnectRESTHelper.refreshToken(configuration.getTokenURL(), + authToken); + } catch (OpenIdConnectRESTHelperException e) { + if (FORCE_LOGOUT_ON_OIDC_REFRESH_ERROR) { + _log.warn("Error refreshing OIDC token, force redirecting to logut URI"); + forceLogout(response); + } else { + _log.error("Refreshing OIDC token on server", e); + } + return; + } + _log.debug("Setting refreshed OIDC token in cache proxy"); + JWTCacheProxy.getInstance().setOIDCToken(user, sessionId, authToken); + } + _log.info("Getting UMA token from OIDC endpoint for scope: " + urlEncodedScope); + umaToken = OpenIdConnectRESTHelper.queryUMAToken(configuration.getTokenURL(), + authToken.getAccessTokenAsBearer(), urlEncodedScope, null); + + } catch (OpenIdConnectRESTHelperException e) { + if (e.hasJSONPayload()) { + if (OpenIdConnectRESTHelper.isInvalidBearerTokenError(e.getResponseString())) { + if (FORCE_LOGOUT_ON_INVALID_OIDC) { + _log.warn("OIDC token is become invalid, forcing redirect to logout URI"); + forceLogout(response); + } else { + _log.error("OIDC token is become invalid, cannot continue"); + } + return; + } else if (OpenIdConnectRESTHelper + .isAccessDeniedNotAuthorizedError(e.getResponseString())) { + _log.info("UMA token is" + (isNotAuthorized ? " still" : "") + + " not authorized with actual OIDC token"); + + isNotAuthorized = true; + authorizationAttempts += 1; + if (authorizationAttempts <= MAX_AUTHORIZATION_RETRY_ATTEMPTS) { + _log.debug("Sleeping " + AUTHORIZATION_RETRY_ATTEMPTS_DELAY + + " ms and refreshing the OIDC"); + try { + Thread.sleep(AUTHORIZATION_RETRY_ATTEMPTS_DELAY); + } catch (InterruptedException ie) { + ie.printStackTrace(); + } + } else { + _log.warn("OIDC token refresh attempts exhausted"); + return; + } + } + } else { + _log.error("Getting UMA token from server", e); + return; + } + } + } while (isNotAuthorized); + } + _log.debug("Setting UMA token in cache proxy"); + + JWTCacheProxy.getInstance().setUMAToken(user, sessionId, umaToken); + } } _log.trace("Current UMA token in use is: {}", umaToken.getTokenEssentials()); @@ -318,7 +276,7 @@ public class SmartGearsPortalValve extends ValveBase { UmaJWTProvider.instance.set(umaToken.getRaw()); } - protected void forceLogout(HttpSession session, HttpServletResponse response) { + protected void forceLogout(HttpServletResponse response) { try { if (!response.isCommitted()) { response.sendRedirect(LOGOUT_URI); From f5479d8f58db60fb5e0670d00a29aaabf76951e1 Mon Sep 17 00:00:00 2001 From: Mauro Mugnaini Date: Tue, 19 Jan 2021 18:00:39 +0100 Subject: [PATCH 3/4] Fixed wrong log messages --- .../gcube/portal/threadlocalexec/SmartGearsPortalValve.java | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java b/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java index 834e1aa..7e577cb 100644 --- a/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java +++ b/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java @@ -180,12 +180,11 @@ public class SmartGearsPortalValve extends ValveBase { JWTToken authToken = JWTCacheProxy.getInstance().getOIDCToken(user, sessionId); if (authToken == null) { - _log.info("OIDC token is null also in cache proxy"); if (FORCE_LOGOUT_ON_MISSING_OIDC) { - _log.warn("OIDC token is null also in cache proxy, force redirecting to logut URI"); + _log.warn("OIDC token is null in cache proxy, force redirecting to logut URI"); forceLogout(response); } else { - _log.error("OIDC token is null also in cache proxy, cannot continue!"); + _log.error("OIDC token is null in cache proxy, cannot continue!"); } return; } From 8e28d139b59c50789bc013798ecab7cd6ae4341a Mon Sep 17 00:00:00 2001 From: Mauro Mugnaini Date: Wed, 20 Jan 2021 00:56:27 +0100 Subject: [PATCH 4/4] Revised implementation that rely completely on cache proxy and ignore the several session objects (with same session ID) that are involved in different calls and threads. In addition to avoid also multiple thread collision that refreshes/requests the same object several times at each call, a specific mutex (per user) has been put in place. --- .../SmartGearsPortalValve.java | 98 ++++++++++--------- 1 file changed, 53 insertions(+), 45 deletions(-) diff --git a/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java b/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java index 7e577cb..c4679a4 100644 --- a/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java +++ b/src/main/java/org/gcube/portal/threadlocalexec/SmartGearsPortalValve.java @@ -32,11 +32,8 @@ import org.gcube.portal.oidc.lr62.LiferayOpenIdConnectConfiguration; import org.slf4j.Logger; import org.slf4j.LoggerFactory; -import com.liferay.portal.kernel.exception.PortalException; -import com.liferay.portal.kernel.exception.SystemException; import com.liferay.portal.model.User; import com.liferay.portal.service.UserLocalServiceUtil; -import com.liferay.portal.util.PortalUtil; /** * @@ -97,54 +94,49 @@ public class SmartGearsPortalValve extends ValveBase { private void checkUMATicket(HttpServletRequest request, HttpServletResponse response, String scope) { _log.debug("Getting current user"); User user = getCurrentUser(request); - User purUser = null; - try { - purUser = PortalUtil.getUser(request); - } catch (PortalException | SystemException e) { - _log.debug("Cannot get user via portal util: {}", e.getMessage()); - } if (user == null) { _log.error("Current user not found, cannot continue"); return; - } else { - _log.debug("Current user is: {} [{}]", user.getScreenName(), user.getEmailAddress()); - if (purUser != null) { - _log.debug("Current PURet user is: {} [{}]", purUser.getScreenName(), purUser.getEmailAddress()); - } else { - _log.debug("Current PURet user null"); - } } + _log.debug("Current user is: {} [{}]", user.getScreenName(), user.getEmailAddress()); + + HttpSession session = request.getSession(false); + if (session == null) { + _log.debug("Session is null, cannot continue"); + return; + } + String sessionId = session.getId(); + _log.debug("Current session ID is {}", sessionId); + String urlEncodedScope = null; + try { + urlEncodedScope = URLEncoder.encode(scope, "UTF-8"); + } catch (UnsupportedEncodingException e) { + // Almost impossible + _log.error("Cannot URL encode scope", e); + return; + } + _log.debug("URL encoded scope is: {}", urlEncodedScope); + JWTToken umaToken = null; synchronized (JWTCacheProxy.getInstance().getMutexFor(user)) { - HttpSession session = request.getSession(false); - if (session == null) { - _log.debug("Session is null, cannot continue"); - return; - } - String sessionId = session.getId(); - _log.debug("Current session ID is {}", sessionId); - String urlEncodedScope = null; - try { - urlEncodedScope = URLEncoder.encode(scope, "UTF-8"); - } catch (UnsupportedEncodingException e) { - // Almost impossible - _log.error("Cannot URL encode scope", e); - return; - } - _log.debug("URL encoded scope is: {}", urlEncodedScope); - - _log.trace("Getting UMA token for session {}", sessionId); + _log.trace("Getting UMA token for user {}, and session {}", user.getScreenName(), sessionId); umaToken = JWTCacheProxy.getInstance().getUMAToken(user, sessionId); if (umaToken != null && !umaToken.isExpired() && umaToken.getAud().contains(urlEncodedScope)) { - _log.trace("Current UMA token is OK [{}]", umaToken.getTokenEssentials()); + _log.trace("Current UMA token is OK {}", umaToken.getTokenEssentials()); } else { if (umaToken != null && umaToken.getAud().contains(urlEncodedScope) && umaToken.isExpired()) { - _log.debug("UMA token is expired, trying to refresh it [{}]", umaToken.getTokenEssentials()); + _log.debug("Suitable UMA token found but is expired, trying to refresh it {}", + umaToken.getTokenEssentials()); + OpenIdConnectConfiguration configuration = LiferayOpenIdConnectConfiguration .getConfiguration(request); try { umaToken = OpenIdConnectRESTHelper.refreshToken(configuration.getTokenURL(), umaToken); - _log.debug("Setting refreshed UMA token in cache proxy [{}]", umaToken.getTokenEssentials()); + _log.debug("Got a refreshed UMA token {}", umaToken.getTokenEssentials()); + + _log.debug("Setting the refreshed UMA token in cache proxy for user {}, and session]", + user.getScreenName(), sessionId); + JWTCacheProxy.getInstance().setUMAToken(user, sessionId, umaToken); } catch (OpenIdConnectRESTHelperException e) { if (e.hasJSONPayload()) { @@ -158,12 +150,16 @@ public class SmartGearsPortalValve extends ValveBase { return; } else if (OpenIdConnectRESTHelper.isTokenNotActiveError(e.getResponseString())) { _log.info("UMA token is no more active, get new one"); + } else { + _log.error("Other UMA token refresh error", e); } } else { - _log.error("Refreshing UMA token on server [" + umaToken.getTokenEssentials() + "]", e); + _log.error("Refreshing UMA token on server " + umaToken.getTokenEssentials(), e); } umaToken = null; - _log.info("Removing inactive UMA token from cache proxy if present"); + _log.debug("Removing inactive UMA token from cache proxy if present for user {} and session {}", + user.getScreenName(), sessionId); + JWTCacheProxy.getInstance().removeUMAToken(user, sessionId); } } @@ -173,10 +169,11 @@ public class SmartGearsPortalValve extends ValveBase { _log.debug("Getting new UMA token for scope {}", urlEncodedScope); } else if (!umaToken.getAud().contains(urlEncodedScope)) { scopeIsChanged = true; - _log.info("Getting new UMA for scope {} since it has been issued for another scope [{}]", + _log.info("Getting new UMA token for scope {} since it has been issued for another scope {}", urlEncodedScope, umaToken.getTokenEssentials()); } - _log.debug("Getting OIDC token from cache proxy"); + _log.debug("Getting OIDC token from cache proxy for user {} and session {}", user.getScreenName(), + sessionId); JWTToken authToken = JWTCacheProxy.getInstance().getOIDCToken(user, sessionId); if (authToken == null) { @@ -187,9 +184,12 @@ public class SmartGearsPortalValve extends ValveBase { _log.error("OIDC token is null in cache proxy, cannot continue!"); } return; + } else { + _log.debug("OIDC token is {}", authToken.getTokenEssentials()); } OpenIdConnectConfiguration configuration = LiferayOpenIdConnectConfiguration .getConfiguration(request); + boolean isNotAuthorized = false; int authorizationAttempts = 0; do { @@ -201,11 +201,14 @@ public class SmartGearsPortalValve extends ValveBase { + "refreshing it to be sure that new grants are present. " + "[attempts: {}]", authorizationAttempts); + + // Resetting the flag to be sure to have correct log message each loop + isNotAuthorized = false; } else if (scopeIsChanged) { _log.info( "Scope is changed, refreshing token to be sure that new grants are present"); } else if (authToken.isExpired()) { - _log.debug("OIDC token is expired, trying to refresh it [{}]", + _log.debug("OIDC token is expired, trying to refresh it {}", authToken.getTokenEssentials()); } try { @@ -227,6 +230,7 @@ public class SmartGearsPortalValve extends ValveBase { umaToken = OpenIdConnectRESTHelper.queryUMAToken(configuration.getTokenURL(), authToken.getAccessTokenAsBearer(), urlEncodedScope, null); + _log.debug("Got new UMA token {}", umaToken.getTokenEssentials()); } catch (OpenIdConnectRESTHelperException e) { if (e.hasJSONPayload()) { if (OpenIdConnectRESTHelper.isInvalidBearerTokenError(e.getResponseString())) { @@ -239,6 +243,7 @@ public class SmartGearsPortalValve extends ValveBase { return; } else if (OpenIdConnectRESTHelper .isAccessDeniedNotAuthorizedError(e.getResponseString())) { + _log.info("UMA token is" + (isNotAuthorized ? " still" : "") + " not authorized with actual OIDC token"); @@ -246,7 +251,7 @@ public class SmartGearsPortalValve extends ValveBase { authorizationAttempts += 1; if (authorizationAttempts <= MAX_AUTHORIZATION_RETRY_ATTEMPTS) { _log.debug("Sleeping " + AUTHORIZATION_RETRY_ATTEMPTS_DELAY - + " ms and refreshing the OIDC"); + + " ms and looping refreshing the OIDC"); try { Thread.sleep(AUTHORIZATION_RETRY_ATTEMPTS_DELAY); } catch (InterruptedException ie) { @@ -264,14 +269,17 @@ public class SmartGearsPortalValve extends ValveBase { } } while (isNotAuthorized); } - _log.debug("Setting UMA token in cache proxy"); + + _log.debug("Setting UMA token in cache proxy for user {} and session {}", user.getScreenName(), + sessionId); JWTCacheProxy.getInstance().setUMAToken(user, sessionId, umaToken); } } + _log.trace("Current UMA token in use is: {}", umaToken.getTokenEssentials()); - _log.debug("Setting UMA token in UMA JWT provider"); + _log.debug("Setting UMA token with jti {} in UMA JWT provider", umaToken.getJti()); UmaJWTProvider.instance.set(umaToken.getRaw()); }