A lot of logs added and rationalized loop

This commit is contained in:
Mauro Mugnaini 2021-01-19 15:04:31 +01:00
parent 9a25509add
commit 1a0f9b5086
1 changed files with 203 additions and 166 deletions

View File

@ -33,8 +33,11 @@ import org.gcube.portal.oidc.lr62.LiferayOpenIdConnectConfiguration;
import org.slf4j.Logger; import org.slf4j.Logger;
import org.slf4j.LoggerFactory; 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.model.User;
import com.liferay.portal.service.UserLocalServiceUtil; import com.liferay.portal.service.UserLocalServiceUtil;
import com.liferay.portal.util.PortalUtil;
/** /**
* *
@ -95,17 +98,31 @@ public class SmartGearsPortalValve extends ValveBase {
private void checkUMATicket(HttpServletRequest request, HttpServletResponse response, String scope) { private void checkUMATicket(HttpServletRequest request, HttpServletResponse response, String scope) {
_log.debug("Getting current user"); _log.debug("Getting current user");
User user = getCurrentUser(request); 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) { if (user == null) {
// Almost impossible
_log.error("Current user not found, cannot continue"); _log.error("Current user not found, cannot continue");
return; 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); HttpSession session = request.getSession(false);
if (session == null) { if (session == null) {
_log.debug("Session is null, cannot continue"); _log.debug("Session is null, cannot continue");
return; return;
} else {
_log.debug("Current session ID is {} and class instance is [{}]", session.getId(),
Integer.toHexString(session.hashCode()));
} }
synchronized (session) {
String urlEncodedScope = null; String urlEncodedScope = null;
try { try {
urlEncodedScope = URLEncoder.encode(scope, "UTF-8"); urlEncodedScope = URLEncoder.encode(scope, "UTF-8");
@ -116,34 +133,42 @@ public class SmartGearsPortalValve extends ValveBase {
} }
_log.debug("URL encoded scope is: {}", urlEncodedScope); _log.debug("URL encoded scope is: {}", urlEncodedScope);
_log.trace("Getting UMA token from session: {}", session); _log.trace("Getting UMA token from session {} [{}]", session.getId(), Integer.toHexString(session.hashCode()));
JWTToken umaToken = JWTTokenUtil.getUMAFromSession(session); JWTToken umaToken = JWTTokenUtil.getUMAFromSession(session);
if (umaToken == null) { if (umaToken == null) {
_log.debug("UMA token not found in session. Trying to get it from cache proxy"); _log.debug("UMA token not found in session. Trying to get it from cache proxy");
umaToken = JWTCacheProxy.getInstance().getUMAToken(user, session); umaToken = JWTCacheProxy.getInstance().getUMAToken(user, session);
} }
if (umaToken != null && !umaToken.isExpired() && umaToken.getAud().contains(urlEncodedScope)) { if (umaToken != null && !umaToken.isExpired() && umaToken.getAud().contains(urlEncodedScope)) {
_log.trace("Current UMA token is OK"); _log.trace("Current UMA token is OK [{}]", umaToken.getTokenEssentials());
if (JWTTokenUtil.getUMAFromSession(session) == null) { if (JWTTokenUtil.getUMAFromSession(session) == null) {
_log.debug("Setting UMA token also in current session"); _log.debug("Setting UMA token also in current session {} [{}]", session.getId(),
Integer.toHexString(session.hashCode()));
JWTTokenUtil.putUMAInSession(umaToken, session); JWTTokenUtil.putUMAInSession(umaToken, session);
} }
} else if (JWTCacheProxy.getInstance().getUMAToken(user, session) != null } else if (JWTCacheProxy.getInstance().getUMAToken(user, session) != null
&& !JWTCacheProxy.getInstance().getUMAToken(user, session).isExpired() && !JWTCacheProxy.getInstance().getUMAToken(user, session).isExpired()
&& JWTCacheProxy.getInstance().getUMAToken(user, session).getAud().contains(urlEncodedScope)) { && 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"); _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); umaToken = JWTCacheProxy.getInstance().getUMAToken(user, session);
JWTTokenUtil.putUMAInSession(umaToken, session); JWTTokenUtil.putUMAInSession(umaToken, session);
} else { } else {
if (umaToken != null && umaToken.getAud().contains(urlEncodedScope) && umaToken.isExpired()) { if (umaToken != null && umaToken.getAud().contains(urlEncodedScope) && umaToken.isExpired()) {
_log.debug("UMA token is expired, trying to refresh it"); _log.debug("UMA token is expired, trying to refresh it [{}]", umaToken.getTokenEssentials());
OpenIdConnectConfiguration configuration = LiferayOpenIdConnectConfiguration.getConfiguration(request); OpenIdConnectConfiguration configuration = LiferayOpenIdConnectConfiguration
.getConfiguration(request);
try { try {
umaToken = OpenIdConnectRESTHelper.refreshToken(configuration.getTokenURL(), umaToken); umaToken = OpenIdConnectRESTHelper.refreshToken(configuration.getTokenURL(), umaToken);
_log.debug("Setting refreshed UMA token in cache proxy"); _log.debug("Setting refreshed UMA token in cache proxy [{}]", umaToken.getTokenEssentials());
JWTCacheProxy.getInstance().setUMAToken(getCurrentUser(request), session, umaToken); JWTCacheProxy.getInstance().setUMAToken(getCurrentUser(request), session, umaToken);
_log.debug("Setting refreshed UMA token in session"); _log.debug("Setting refreshed UMA token in session {} [{}]", session.getId(),
Integer.toHexString(session.hashCode()));
JWTTokenUtil.putUMAInSession(umaToken, session); JWTTokenUtil.putUMAInSession(umaToken, session);
} catch (OpenIdConnectRESTHelperException e) { } catch (OpenIdConnectRESTHelperException e) {
if (e.hasJSONPayload()) { if (e.hasJSONPayload()) {
@ -159,12 +184,16 @@ public class SmartGearsPortalValve extends ValveBase {
_log.info("UMA token is no more active, get new one"); _log.info("UMA token is no more active, get new one");
} }
} else { } else {
_log.error("Refreshing UMA token on server", e); _log.error("Refreshing UMA token on server [" + umaToken.getTokenEssentials() + "]", e);
} }
umaToken = null; umaToken = null;
_log.info("Removing probably inactive OIDC token from session"); _log.info("Removing probably inactive OIDC token from session {} [{}}", session.getId(),
Integer.toHexString(session.hashCode()));
JWTTokenUtil.removeOIDCFromSession(session); JWTTokenUtil.removeOIDCFromSession(session);
_log.info("Removing all inactive UMA token from session and from cache proxy if present"); _log.info("Removing all inactive UMA token from session {} [{}] and from cache proxy if present",
session.getId(), Integer.toHexString(session.hashCode()));
JWTTokenUtil.removeUMAFromSession(session); JWTTokenUtil.removeUMAFromSession(session);
JWTCacheProxy.getInstance().removeUMAToken(user, session); JWTCacheProxy.getInstance().removeUMAToken(user, session);
} }
@ -175,10 +204,12 @@ public class SmartGearsPortalValve extends ValveBase {
_log.debug("Getting new UMA token for scope {}", urlEncodedScope); _log.debug("Getting new UMA token for scope {}", urlEncodedScope);
} else if (!umaToken.getAud().contains(urlEncodedScope)) { } else if (!umaToken.getAud().contains(urlEncodedScope)) {
scopeIsChanged = true; scopeIsChanged = true;
_log.info("UMA token has been issued for another scope ({}). Getting new one for scope: {}", _log.info("Getting new UMA for scope {} since it has been issued for another scope [{}]",
umaToken.getAud(), urlEncodedScope); urlEncodedScope, umaToken.getTokenEssentials());
} }
_log.debug("Getting OIDC token from session"); _log.debug("Getting OIDC token from session {} [{}]", session.getId(),
Integer.toHexString(session.hashCode()));
JWTToken authToken = JWTTokenUtil.getOIDCFromSession(session); JWTToken authToken = JWTTokenUtil.getOIDCFromSession(session);
if (authToken == null) { if (authToken == null) {
_log.debug("OIDC token not found in session. Trying to get it from cache proxy"); _log.debug("OIDC token not found in session. Trying to get it from cache proxy");
@ -188,21 +219,21 @@ public class SmartGearsPortalValve extends ValveBase {
if (FORCE_LOGOUT_ON_MISSING_OIDC) { 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 also in cache proxy, force redirecting to logut URI");
forceLogout(session, response); forceLogout(session, response);
return;
} else { } else {
_log.error("OIDC token is null also in cache proxy, cannot continue!"); _log.error("OIDC token is null also in cache proxy, cannot continue!");
return;
} }
return;
} else { } else {
_log.debug("Setting OIDC token took from cache proxy in session"); _log.debug("Setting OIDC token took from cache proxy in session {} [{}}", session.getId(),
Integer.toHexString(session.hashCode()));
JWTTokenUtil.putOIDCInSession(authToken, session); JWTTokenUtil.putOIDCInSession(authToken, session);
} }
} }
OpenIdConnectConfiguration configuration = LiferayOpenIdConnectConfiguration.getConfiguration(request); OpenIdConnectConfiguration configuration = LiferayOpenIdConnectConfiguration.getConfiguration(request);
boolean OK = false;
boolean isNotAuthorized = false; boolean isNotAuthorized = false;
int authorizationAttempts = 0; int authorizationAttempts = 0;
while (!OK) { do {
try { try {
if (isNotAuthorized || scopeIsChanged || authToken.isExpired()) { if (isNotAuthorized || scopeIsChanged || authToken.isExpired()) {
if (isNotAuthorized) { if (isNotAuthorized) {
@ -212,9 +243,11 @@ public class SmartGearsPortalValve extends ValveBase {
+ "[attempts: {}]", + "[attempts: {}]",
authorizationAttempts); authorizationAttempts);
} else if (scopeIsChanged) { } else if (scopeIsChanged) {
_log.info("Scope is changed, refreshing token to be sure that new grants are present"); _log.info(
"Scope is changed, refreshing token to be sure that new grants are present");
} else if (authToken.isExpired()) { } 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 { try {
authToken = OpenIdConnectRESTHelper.refreshToken(configuration.getTokenURL(), authToken = OpenIdConnectRESTHelper.refreshToken(configuration.getTokenURL(),
@ -236,7 +269,6 @@ public class SmartGearsPortalValve extends ValveBase {
umaToken = OpenIdConnectRESTHelper.queryUMAToken(configuration.getTokenURL(), umaToken = OpenIdConnectRESTHelper.queryUMAToken(configuration.getTokenURL(),
authToken.getAccessTokenAsBearer(), urlEncodedScope, null); authToken.getAccessTokenAsBearer(), urlEncodedScope, null);
OK = true;
} catch (OpenIdConnectRESTHelperException e) { } catch (OpenIdConnectRESTHelperException e) {
if (e.hasJSONPayload()) { if (e.hasJSONPayload()) {
if (OpenIdConnectRESTHelper.isInvalidBearerTokenError(e.getResponseString())) { if (OpenIdConnectRESTHelper.isInvalidBearerTokenError(e.getResponseString())) {
@ -272,22 +304,27 @@ public class SmartGearsPortalValve extends ValveBase {
return; return;
} }
} }
} while (isNotAuthorized);
} }
} _log.debug("Setting UMA token in cache proxy and in session {} [{}]", session.getId(),
_log.debug("Setting UMA token in cache proxy and in session"); Integer.toHexString(session.hashCode()));
JWTCacheProxy.getInstance().setUMAToken(user, session, umaToken); JWTCacheProxy.getInstance().setUMAToken(user, session, umaToken);
JWTTokenUtil.putUMAInSession(umaToken, session); JWTTokenUtil.putUMAInSession(umaToken, session);
} }
_log.trace("Current UMA token audience is: {}", umaToken.getAud()); _log.trace("Current UMA token in use is: {}", umaToken.getTokenEssentials());
_log.debug("Setting UMA token in UMA JWT provider"); _log.debug("Setting UMA token in UMA JWT provider");
UmaJWTProvider.instance.set(umaToken.getRaw()); UmaJWTProvider.instance.set(umaToken.getRaw());
} }
}
protected void forceLogout(HttpSession session, HttpServletResponse response) { protected void forceLogout(HttpSession session, HttpServletResponse response) {
try { try {
if (!response.isCommitted()) {
response.sendRedirect(LOGOUT_URI); response.sendRedirect(LOGOUT_URI);
} else {
_log.warn("Cannot redirect to logout URI since the response is already commited");
}
} catch (IOException e) { } catch (IOException e) {
_log.error("Cannot redirect to logout URI: " + LOGOUT_URI, e); _log.error("Cannot redirect to logout URI: " + LOGOUT_URI, e);
} }