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()); }