Moved to liferay's portal `Log` class from `slf4j` to be configurable from portal admin

This commit is contained in:
Mauro Mugnaini 2024-11-12 12:14:35 +01:00
parent 3eaf89964e
commit 96b2489fbe
Signed by: mauro.mugnaini
GPG Key ID: 2440CFD0EB321EA8
1 changed files with 117 additions and 58 deletions

View File

@ -14,18 +14,18 @@ import org.gcube.oidc.rest.JWTToken;
import org.gcube.oidc.rest.OpenIdConnectConfiguration;
import org.gcube.oidc.rest.OpenIdConnectRESTHelper;
import org.gcube.oidc.rest.OpenIdConnectRESTHelperException;
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.kernel.log.Log;
import com.liferay.portal.kernel.log.LogFactoryUtil;
import com.liferay.portal.model.User;
import com.liferay.portal.service.UserLocalServiceUtil;
import com.liferay.portal.util.PortalUtil;
public class OIDCUmaUtil {
private static final Logger log = LoggerFactory.getLogger(OIDCUmaUtil.class);
private static final Log log = LogFactoryUtil.getLog(OIDCUmaUtil.class);
private static final boolean REFRESH_UMA_TOKEN = false;
private static final String LOGOUT_URI = "/c/portal/logout";
@ -48,7 +48,9 @@ public class OIDCUmaUtil {
String infraContext) {
try {
log.debug("Getting client token from server");
if (log.isDebugEnabled()) {
log.debug("Getting client token from server");
}
JWTToken clientToken = OpenIdConnectRESTHelper.queryClientToken(clientId, clientSecret, tokenURL);
provideClientUMATokenInThreadLocal(clientToken.getAccessTokenAsBearer(), tokenURL, infraContext);
} catch (Exception e) {
@ -67,9 +69,13 @@ public class OIDCUmaUtil {
log.error("Cannot URL encode context", e);
return;
}
log.debug("URL encoded context is: {}", encodedContext);
if (log.isDebugEnabled()) {
log.debug("URL encoded context is: " + encodedContext);
}
try {
log.debug("Getting UMA token from server");
if (log.isDebugEnabled()) {
log.debug("Getting UMA token from server");
}
JWTToken umaToken = OpenIdConnectRESTHelper.queryUMAToken(tokenURL, clientAuthorizationBearer,
encodedContext, null);
@ -146,7 +152,8 @@ public class OIDCUmaUtil {
try {
return getUMAToken(request,
UserLocalServiceUtil.getUserByScreenName(PortalUtil.getCompanyId(request), screenName), scope, temporary);
UserLocalServiceUtil.getUserByScreenName(PortalUtil.getCompanyId(request), screenName), scope,
temporary);
} catch (PortalException | SystemException e) {
throw new UMAException("Cannot get liferay user from companyId and screenName", e);
@ -167,12 +174,12 @@ public class OIDCUmaUtil {
return getUMAToken(request, user, request.getSession(false), scope, temporary);
}
// public static JWTToken getUMAToken(HttpServletRequest request, User user, HttpSession session, String scope)
// throws InvalidTokenException, MissingTokenException, RefreshException, NotAuthorizedException,
// UMAException {
//
// return getUMAToken(request, user, session, scope, true);
// }
// public static JWTToken getUMAToken(HttpServletRequest request, User user, HttpSession session, String scope)
// throws InvalidTokenException, MissingTokenException, RefreshException, NotAuthorizedException,
// UMAException {
//
// return getUMAToken(request, user, session, scope, true);
// }
private static JWTToken getUMAToken(HttpServletRequest request, User user, HttpSession session, String scope,
boolean temporary) throws InvalidTokenException, MissingTokenException, MissingRefreshTokenException,
@ -182,14 +189,20 @@ public class OIDCUmaUtil {
log.error("User is null, cannot continue");
return null;
}
log.debug("Current user is: {} [{}]", user.getScreenName(), user.getEmailAddress());
if (log.isDebugEnabled()) {
log.debug("Current user is: " + user.getScreenName() + " [" + user.getEmailAddress() + "]");
}
if (session == null) {
log.debug("Session is null, cannot continue");
if (log.isDebugEnabled()) {
log.debug("Session is null, cannot continue");
}
throw new UMAException("Session is null");
}
String sessionId = session.getId();
log.debug("Current session ID is {}", sessionId);
if (log.isDebugEnabled()) {
log.debug("Current session ID is " + sessionId);
}
String urlEncodedScope = null;
try {
@ -199,29 +212,39 @@ public class OIDCUmaUtil {
log.error("Cannot URL encode scope", e);
return null;
}
log.debug("URL encoded scope is: {}", urlEncodedScope);
if (log.isDebugEnabled()) {
log.debug("URL encoded scope is: " + urlEncodedScope);
}
JWTToken umaToken = null;
JWTCacheProxy jwtCacheProxy = JWTCacheProxy.getInstance();
synchronized (jwtCacheProxy.getMutexFor(user)) {
log.trace("Getting UMA token for user {}, and session {}", user.getScreenName(), sessionId);
if (log.isTraceEnabled()) {
log.trace("Getting UMA token for user " + user.getScreenName() + ", and session " + sessionId);
}
umaToken = jwtCacheProxy.getUMAToken(user, sessionId);
if (umaToken != null && !umaToken.isExpired() && umaToken.getAud().contains(urlEncodedScope)) {
log.trace("Current UMA token is OK {}", umaToken.getTokenEssentials());
if (log.isTraceEnabled()) {
log.trace("Current UMA token is OK " + umaToken.getTokenEssentials());
}
} else {
if (umaToken != null && umaToken.getAud().contains(urlEncodedScope) && umaToken.isExpired()) {
if (REFRESH_UMA_TOKEN) {
log.debug("Suitable UMA token found but is expired, trying to refresh it {}",
umaToken.getTokenEssentials());
if (log.isDebugEnabled()) {
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("Got a refreshed UMA token {}", umaToken.getTokenEssentials());
if (log.isDebugEnabled()) {
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);
log.debug("Setting the refreshed UMA token in cache proxy for user "
+ user.getScreenName() + ", and session " + sessionId);
}
// This is independent from "temporary" setting since is a refresh of an expired token
// issued for the same context
@ -236,23 +259,30 @@ public class OIDCUmaUtil {
log.error("Other unexpected UMA token refresh error", e);
}
} else {
log.warn("Refreshing UMA token on server for {}: {}", umaToken.getTokenEssentials(), e.getMessage());
log.warn("Refreshing UMA token on server for " + umaToken.getTokenEssentials() + ": "
+ e.getMessage());
}
umaToken = null;
log.debug(
"Removing inactive UMA token from cache proxy if present for user {} and session {}",
user.getScreenName(), sessionId);
if (log.isDebugEnabled()) {
log.debug(
"Removing inactive UMA token from cache proxy if present for user "
+ user.getScreenName() + " and session " + sessionId);
}
jwtCacheProxy.removeUMAToken(user, sessionId);
}
} else {
log.debug("Suitable UMA token found but it is expired."
+ "It will be replaced with new one according to settings {}",
umaToken.getTokenEssentials());
if (log.isDebugEnabled()) {
log.debug("Suitable UMA token found but it is expired."
+ "It will be replaced with new one according to settings "
+ umaToken.getTokenEssentials());
}
umaToken = null;
log.debug("Removing inactive UMA token from cache proxy if present for user {} and session {}",
user.getScreenName(), sessionId);
if (log.isDebugEnabled()) {
log.debug("Removing inactive UMA token from cache proxy if present for user "
+ user.getScreenName() + " and session " + sessionId);
}
jwtCacheProxy.removeUMAToken(user, sessionId);
}
@ -260,14 +290,19 @@ public class OIDCUmaUtil {
if (umaToken == null || !umaToken.getAud().contains(urlEncodedScope)) {
boolean scopeIsChanged = false;
if (umaToken == null) {
log.debug("Getting new UMA token for scope {}", urlEncodedScope);
if (log.isDebugEnabled()) {
log.debug("Getting new UMA token for scope " + urlEncodedScope);
}
} else if (!umaToken.getAud().contains(urlEncodedScope)) {
scopeIsChanged = true;
log.info("Getting new UMA token for scope {} since it has been issued for another scope {}",
urlEncodedScope, umaToken.getTokenEssentials());
log.info("Getting new UMA token for scope " + urlEncodedScope
+ " since it has been issued for another scope " + umaToken.getTokenEssentials());
}
if (log.isDebugEnabled()) {
log.debug(
"Getting OIDC token from cache proxy for user " + user.getScreenName() + " and session "
+ sessionId);
}
log.debug("Getting OIDC token from cache proxy for user {} and session {}", user.getScreenName(),
sessionId);
JWTToken authToken = jwtCacheProxy.getOIDCToken(user, sessionId);
if (authToken == null) {
@ -275,7 +310,9 @@ public class OIDCUmaUtil {
} else if (!authToken.hasRefreshToken()) {
throw new MissingRefreshTokenException("Missing refresh token in OIDC access token");
} else {
log.debug("OIDC token is {}", authToken.getTokenEssentials());
if (log.isDebugEnabled()) {
log.debug("OIDC token is " + authToken.getTokenEssentials());
}
}
OpenIdConnectConfiguration configuration = LiferayOpenIdConnectConfiguration
.getConfiguration(request);
@ -289,8 +326,7 @@ public class OIDCUmaUtil {
log.info(
"UMA token is not authorized with current OIDC token, "
+ "refreshing it to be sure that new grants are present. "
+ "[attempts: {}]",
authorizationAttempts);
+ "[attempts: " + authorizationAttempts + "]");
// Resetting the flag to be sure to have correct log message each loop
isNotAuthorized = false;
@ -302,8 +338,10 @@ public class OIDCUmaUtil {
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());
if (log.isDebugEnabled()) {
log.debug("OIDC token is expired, trying to refresh it "
+ authToken.getTokenEssentials());
}
}
try {
authToken = OpenIdConnectRESTHelper.refreshToken(configuration.getTokenURL(),
@ -318,7 +356,9 @@ public class OIDCUmaUtil {
umaToken = OpenIdConnectRESTHelper.queryUMAToken(configuration.getTokenURL(),
authToken.getAccessTokenAsBearer(), urlEncodedScope, null);
log.debug("Got new UMA token {}", umaToken.getTokenEssentials());
if (log.isDebugEnabled()) {
log.debug("Got new UMA token " + umaToken.getTokenEssentials());
}
} catch (OpenIdConnectRESTHelperException e) {
if (e.hasJSONPayload()) {
if (OpenIdConnectRESTHelper.isInvalidBearerTokenError(e.getResponseString())) {
@ -332,8 +372,10 @@ public class OIDCUmaUtil {
isNotAuthorized = true;
authorizationAttempts += 1;
if (authorizationAttempts <= MAX_AUTHORIZATION_RETRY_ATTEMPTS) {
log.debug("Sleeping " + AUTHORIZATION_RETRY_ATTEMPTS_DELAY
+ " ms and looping refreshing the OIDC");
if (log.isDebugEnabled()) {
log.debug("Sleeping " + AUTHORIZATION_RETRY_ATTEMPTS_DELAY
+ " ms and looping refreshing the OIDC");
}
try {
Thread.sleep(AUTHORIZATION_RETRY_ATTEMPTS_DELAY);
} catch (InterruptedException ie) {
@ -351,8 +393,10 @@ public class OIDCUmaUtil {
}
if (!temporary) {
log.debug("Setting UMA token in cache proxy for user {} and session {}", user.getScreenName(),
sessionId);
if (log.isDebugEnabled()) {
log.debug("Setting UMA token in cache proxy for user " + user.getScreenName() + " and session "
+ sessionId);
}
jwtCacheProxy.setUMAToken(user, sessionId, umaToken);
}
@ -366,22 +410,30 @@ public class OIDCUmaUtil {
try {
JWTToken umaToken = getUMAToken(request, user, session, scope, false);
log.trace("Current UMA token in use is: {}", umaToken.getTokenEssentials());
if (log.isTraceEnabled()) {
log.trace("Current UMA token in use is: " + umaToken.getTokenEssentials());
}
provideTokensInThreadlocal(umaToken);
} catch (MissingTokenException e) {
if (FORCE_LOGOUT_ON_MISSING_OIDC) {
log.debug("OIDC token is null in cache proxy, force redirecting to logout URI");
if (log.isDebugEnabled()) {
log.debug("OIDC token is null in cache proxy, force redirecting to logout URI");
}
forceLogout(response);
} else {
log.debug("OIDC token is null in cache proxy, cannot continue");
if (log.isDebugEnabled()) {
log.debug("OIDC token is null in cache proxy, cannot continue");
}
}
log.debug("Removing UMA ticket from proxy");
JWTCacheProxy.getInstance().removeUMAToken(user, session.getId());
return;
} catch (MissingRefreshTokenException e) {
if (FORCE_LOGOUT_ON_MISSING_OIDC_REFRESH_TOKEN) {
log.debug("Force redirecting to logout URI: {}", e.getMessage());
if (log.isDebugEnabled()) {
log.debug("Force redirecting to logout URI: " + e.getMessage());
}
forceLogout(response);
} else {
log.info(e.getMessage());
@ -394,7 +446,7 @@ public class OIDCUmaUtil {
return;
} catch (RefreshTokenExpiredException e) {
if (FORCE_LOGOUT_ON_OIDC_REFRESH_ERROR) {
log.info("Force redirecting to logout URI for {}: {}", user.getScreenName(), e.getMessage());
log.info("Force redirecting to logout URI for " + user.getScreenName() + ": " + e.getMessage());
forceLogout(response);
} else {
log.info(e.getMessage());
@ -407,17 +459,22 @@ public class OIDCUmaUtil {
return;
} catch (RefreshException e) {
if (FORCE_LOGOUT_ON_OIDC_REFRESH_ERROR) {
log.debug("Cannot refresh OIDC token, force redirect for {} to logout URI: {}", user.getScreenName(),
e.getCause().getMessage());
if (log.isDebugEnabled()) {
log.debug(
"Cannot refresh OIDC token, force redirect for " + user.getScreenName() + " to logout URI: "
+ e.getCause().getMessage());
}
forceLogout(response);
} else {
log.warn("Error refreshing OIDC token: {}", e.getCause().getMessage());
log.warn("Error refreshing OIDC token: " + e.getCause().getMessage());
}
return;
} catch (InvalidTokenException e) {
if (FORCE_LOGOUT_ON_INVALID_TOKEN) {
log.debug("OIDC token is become invalid, forcing redirect to logout URI");
if (log.isDebugEnabled()) {
log.debug("OIDC token is become invalid, forcing redirect to logout URI");
}
forceLogout(response);
} else {
log.warn("OIDC token is become invalid, cannot continue");
@ -432,7 +489,9 @@ public class OIDCUmaUtil {
}
public static void provideTokensInThreadlocal(JWTToken umaTokens) {
log.debug("Setting UMA token with jti {} in AccessToken provider", umaTokens.getJti());
if (log.isDebugEnabled()) {
log.debug("Setting UMA token with jti " + umaTokens.getJti() + " in AccessToken provider");
}
AccessTokenProvider.instance.set(JWTTokenUtil.getAccessTokenString(umaTokens));
}