From 6d98ca3e72f2a1a6d64577c132b1bd0bf4c3c146 Mon Sep 17 00:00:00 2001 From: Abhilash Kishore Date: Thu, 30 Jun 2022 17:13:19 -0700 Subject: [PATCH] Logging improvements in X509AuthenticationUtil and X509ZNodeGroupAclProvider (#83) Logging improvements in X509AuthenticationUtil and X509ZNodeGroupAclProvider --- .../server/auth/X509AuthenticationUtil.java | 50 +++++++------------ .../groupacl/X509ZNodeGroupAclProvider.java | 33 +++++------- 2 files changed, 31 insertions(+), 52 deletions(-) diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/X509AuthenticationUtil.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/X509AuthenticationUtil.java index bec86d36e02..5133d8d36a6 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/X509AuthenticationUtil.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/X509AuthenticationUtil.java @@ -71,12 +71,12 @@ public static X509KeyManager createKeyManager(ZKConfig config) { X509KeyManager km = null; if (keyStoreLocation.isEmpty()) { - LOG.warn("X509AuthenticationUtil::keystore not specified for client connection"); + LOG.warn("Key store location not specified for SSL"); } else { try { km = X509Util.createKeyManager(keyStoreLocation, keyStorePassword, keyStoreTypeProp); } catch (X509Exception.KeyManagerException e) { - LOG.error("X509AuthenticationUtil::Failed to create key manager", e); + LOG.error("Failed to create key manager", e); } } return km; @@ -103,14 +103,14 @@ public static X509TrustManager createTrustManager(ZKConfig config) { X509TrustManager tm = null; if (trustStoreLocation.isEmpty()) { - LOG.warn("X509AuthenticationUtil::Truststore not specified for client connection"); + LOG.warn("Truststore location not specified for SSL"); } else { try { tm = X509Util .createTrustManager(trustStoreLocation, trustStorePassword, trustStoreTypeProp, crlEnabled, ocspEnabled, hostnameVerificationEnabled, false); } catch (X509Exception.TrustManagerException e) { - LOG.error("X509AuthenticationUtil::Failed to create trust manager", e); + LOG.error("Failed to create trust manager", e); } } return tm; @@ -137,8 +137,7 @@ public static String getClientId(X509Certificate clientCert) { try { return X509AuthenticationUtil.matchAndExtractSAN(clientCert); } catch (Exception ce) { - LOG.warn("X509AuthenticationUtil::getClientId(): failed to match and extract a" - + " client ID from SAN! Using Subject DN instead...", ce); + LOG.warn("Failed to match and extract a client ID from SAN. Using Subject DN instead.", ce); } } // return Subject DN by default @@ -174,39 +173,32 @@ private static String matchAndExtractSAN(X509Certificate clientCert) String extractRegex = X509AuthenticationConfig.getInstance().getClientCertIdSanExtractRegex(); int extractMatcherGroupIndex = X509AuthenticationConfig.getInstance().getClientCertIdSanExtractMatcherGroupIndex(); - LOG.info("X509AuthenticationUtil::matchAndExtractSAN(): Using SAN in the client cert " - + "for client ID! matchType: {}, matchRegex: {}, extractRegex: {}, " + LOG.debug("Using SAN from client cert to extract client ID. matchType: {}, matchRegex: {}, extractRegex: {}, " + "extractMatcherGroupIndex: {}", matchType, matchRegex, extractRegex, extractMatcherGroupIndex); if (matchRegex == null || extractRegex == null || matchType < 0 || matchType > 8) { // SAN extension must be in the range of [0, 8]. - // See GeneralName object defined in RFC 5280 (The ASN.1 definition of the - // SubjectAltName extension) - String errStr = "X509AuthenticationUtil::matchAndExtractSAN(): ClientCert ID type " - + "SAN was provided but matchType or matchRegex given is invalid! matchType: " + matchType - + " matchRegex: " + matchRegex; + // See GeneralName object defined in RFC 5280 (The ASN.1 definition of the SubjectAltName extension) + String errStr = "Client cert ID type 'SAN' was provided but matchType or matchRegex given is invalid! " + + "matchType: " + matchType + " matchRegex: " + matchRegex; LOG.error(errStr); throw new IllegalArgumentException(errStr); } // filter by match type and match regex - LOG.info("X509AuthenticationUtil::matchAndExtractSAN(): number of SAN entries found in" - + " clientCert: " + clientCert.getSubjectAlternativeNames().size()); + LOG.debug("Number of SAN entries found in client cert: " + clientCert.getSubjectAlternativeNames().size()); Pattern matchPattern = Pattern.compile(matchRegex); Collection> matched = clientCert.getSubjectAlternativeNames().stream().filter( list -> list.get(0).equals(matchType) && matchPattern.matcher((CharSequence) list.get(1)) .find()).collect(Collectors.toList()); - LOG.info( - "X509AuthenticationUtil::matchAndExtractSAN(): number of SAN entries matched: " + matched - .size() + ". Printing all matches..."); + LOG.debug("Number of SAN entries matched: " + matched.size() + ". Printing all matches..."); for (List match : matched) { - LOG.info(" Match: (" + match.get(0) + ", " + match.get(1) + ")"); + LOG.debug("Match: (" + match.get(0) + ", " + match.get(1) + ")"); } // if there are more than one match or 0 matches, throw an error if (matched.size() != 1) { - String errStr = "X509AuthenticationUtil::matchAndExtractSAN(): 0 or multiple " - + "matches found in SAN! Please fix match type and regex so that exactly one match " + String errStr = "Zero or multiple matches found in SAN! Please fix match type and regex so that exactly one match " + "is found."; LOG.error(errStr); throw new IllegalArgumentException(errStr); @@ -218,12 +210,10 @@ private static String matchAndExtractSAN(X509Certificate clientCert) if (matcher.find()) { // If extractMatcherGroupIndex is not given, return the 1st index by default String result = matcher.group(extractMatcherGroupIndex); - LOG.info("X509AuthenticationUtil::matchAndExtractSAN(): returning extracted " - + "client ID: {} using Matcher group index: {}", result, extractMatcherGroupIndex); + LOG.debug("Returning extracted client ID: {} using Matcher group index: {}", result, extractMatcherGroupIndex); return result; } - String errStr = "X509AuthenticationUtil::matchAndExtractSAN(): failed to find an " - + "extract substring! Please review the extract regex!"; + String errStr = "Failed to find an extract substring to determine client ID. Please review the extract regex."; LOG.error(errStr); throw new IllegalArgumentException(errStr); } @@ -240,8 +230,7 @@ public static X509Certificate getAuthenticatedClientCert(ServerCnxn cnxn, X509Tr X509Certificate[] certChain = (X509Certificate[]) cnxn.getClientCertificateChain(); if (certChain == null || certChain.length == 0) { - String errMsg = - "X509AuthenticationUtil::getAndAuthenticateClientCert(): No X509 certificate is found in cert chain."; + String errMsg = "No X509 certificate is found in cert chain."; LOG.error(errMsg); throw new KeeperException.AuthFailedException(); } @@ -249,9 +238,7 @@ public static X509Certificate getAuthenticatedClientCert(ServerCnxn cnxn, X509Tr X509Certificate clientCert = certChain[0]; if (trustManager == null) { - String errMsg = - "X509AuthenticationUtil::getAndAuthenticateClientCert(): No trust manager available to authenticate session 0x" - + Long.toHexString(cnxn.getSessionId()); + String errMsg = "No trust manager available to authenticate session 0x"+ Long.toHexString(cnxn.getSessionId()); LOG.error(errMsg); throw new KeeperException.AuthFailedException(); } @@ -260,8 +247,7 @@ public static X509Certificate getAuthenticatedClientCert(ServerCnxn cnxn, X509Tr // Authenticate client certificate trustManager.checkClientTrusted((X509Certificate[]) cnxn.getClientCertificateChain(), clientCert.getPublicKey().getAlgorithm()); } catch (CertificateException ce) { - String errMsg = - "X509AuthenticationUtil::getAndAuthenticateClientCert(): Failed to trust certificate for session 0x" + Long.toHexString(cnxn.getSessionId()); + String errMsg = "Failed to trust certificate for session 0x" + Long.toHexString(cnxn.getSessionId()); LOG.error(errMsg, ce); throw new KeeperException.AuthFailedException(); } diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/znode/groupacl/X509ZNodeGroupAclProvider.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/znode/groupacl/X509ZNodeGroupAclProvider.java index 291ef6a54d6..283f6266123 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/znode/groupacl/X509ZNodeGroupAclProvider.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/znode/groupacl/X509ZNodeGroupAclProvider.java @@ -72,7 +72,6 @@ */ public class X509ZNodeGroupAclProvider extends ServerAuthenticationProvider { private static final Logger LOG = LoggerFactory.getLogger(X509ZNodeGroupAclProvider.class); - private final String logStrPrefix = this.getClass().getName() + ":: "; private final X509TrustManager trustManager; private final X509KeyManager keyManager; // Although using "volatile" keyword with double checked locking could prevent the undesired @@ -100,8 +99,7 @@ public KeeperException.Code handleAuthentication(ServerObjs serverObjs, byte[] a return KeeperException.Code.AUTHFAILED; } catch (Exception e) { // Failed to extract clientId from certificate - LOG.error(logStrPrefix + "Failed to extract URI from certificate for session 0x{}", - Long.toHexString(cnxn.getSessionId()), e); + LOG.error("Failed to extract URI from certificate for session 0x{}", Long.toHexString(cnxn.getSessionId()), e); return KeeperException.Code.OK; } @@ -111,7 +109,7 @@ public KeeperException.Code handleAuthentication(ServerObjs serverObjs, byte[] a // Initially assign AuthInfo to the new connection by triggering the helper update method. helper.updateDomainBasedAuthInfo(cnxn); } catch (Exception e) { - LOG.error(logStrPrefix + "Failed to authorize session 0x{}", Long.toHexString(cnxn.getSessionId()), e); + LOG.error("Failed to authorize session 0x{}", Long.toHexString(cnxn.getSessionId()), e); } // Authentication is done regardless of whether authorization is done or not. @@ -168,12 +166,10 @@ private ClientUriDomainMappingHelper getUriDomainMappingHelper(ZooKeeperServer z // If no domain name is found, use client Id as default domain name clientUriToDomainNames.getOrDefault(clientId, Collections.singleton(clientId))); } catch (UnsupportedOperationException unsupportedEx) { - LOG.info(logStrPrefix + "Cannot update AuthInfo for session 0x{} since the operation is not supported.", + LOG.info("Cannot update AuthInfo for session 0x{} since the operation is not supported.", Long.toHexString(cnxn.getSessionId())); } catch (KeeperException.AuthFailedException authEx) { - LOG.error(logStrPrefix - + "Failed to authenticate session 0x{} for AuthInfo update. " - + "Revoking all of its ZNodeGroupAcl AuthInfo.", + LOG.error("Failed to authenticate session 0x{} for AuthInfo update. Revoking all of its ZNodeGroupAcl AuthInfo.", Long.toHexString(cnxn.getSessionId()), authEx); try { cnxn.getAuthInfo() @@ -181,18 +177,17 @@ private ClientUriDomainMappingHelper getUriDomainMappingHelper(ZooKeeperServer z .filter(id -> isZnodeGroupAclScheme(id.getScheme())) .forEach(id -> cnxn.removeAuthInfo(id)); } catch (Exception ex) { - LOG.error(logStrPrefix + "Failed to revoke AuthInfo for session 0x{}.", + LOG.error("Failed to revoke AuthInfo for session 0x{}.", Long.toHexString(cnxn.getSessionId()), ex); } } catch (Exception e) { - LOG.error(logStrPrefix - + "Failed to update AuthInfo for session 0x{}. Keep the existing ZNodeGroupAcl AuthInfo.", + LOG.error("Failed to update AuthInfo for session 0x{}. Keep the existing ZNodeGroupAcl AuthInfo.", Long.toHexString(cnxn.getSessionId()), e); // TODO Emitting errors to ZK metrics so the out-of-date AuthInfo can trigger alerts and get fixed. } }); uriDomainMappingHelper = helper; - LOG.info(logStrPrefix + "New UriDomainMappingHelper has been instantiated."); + LOG.info("New UriDomainMappingHelper has been instantiated."); } } } @@ -235,14 +230,12 @@ private void assignAuthInfo(ServerCnxn cnxn, String clientId, Set domain // If connection filtering feature is turned on, use connection filtering instead of normal authorization String serverNamespace = X509AuthenticationConfig.getInstance().getZnodeGroupAclServerDedicatedDomain(); if (domains.contains(serverNamespace)) { - LOG.info(logStrPrefix - + "Id '{}' belongs to domain that matches server namespace '{}', authorized for access.", + LOG.info("Id '{}' belongs to domain that matches server namespace '{}', authorized for access.", clientId, serverNamespace); // Same as storing authenticated user info in X509AuthenticationProvider newAuthIds.add(new Id(getScheme(), clientId)); } else { - LOG.info(logStrPrefix - + "Id '{}' does not belong to domain that matches server namespace '{}', disconnected the connection.", + LOG.info("Id '{}' does not belong to domain that matches server namespace '{}', disconnected the connection.", clientId, serverNamespace); cnxn.close(ServerCnxn.DisconnectReason.SSL_AUTH_FAILURE); } @@ -257,16 +250,16 @@ private void assignAuthInfo(ServerCnxn cnxn, String clientId, Set domain // Remove all previously assigned ZNodeGroupAcls that are no longer valid. if (isZnodeGroupAclScheme(id.getScheme()) && !newAuthIds.contains(id)) { cnxn.removeAuthInfo(id); - LOG.info(logStrPrefix + "Authenticated Id 'scheme: {}, id: {}' has been removed from session 0x{}.", - id.getScheme(), id.getId(), Long.toHexString(cnxn.getSessionId())); + LOG.info("Authenticated Id 'scheme: {}, id: {}' has been removed from session 0x{} of host {}.", + id.getScheme(), id.getId(), Long.toHexString(cnxn.getSessionId()), cnxn.getHostAddress()); } }); newAuthIds.stream().forEach(id -> { if (!currentCnxnAuthIds.contains(id)) { cnxn.addAuthInfo(id); - LOG.info(logStrPrefix + "Authenticated Id 'scheme: {}, id: {}' has been added to session 0x{}.", id.getScheme(), - id.getId(), Long.toHexString(cnxn.getSessionId())); + LOG.info("Authenticated Id 'scheme: {}, id: {}' has been added to session 0x{} from host {}.", + id.getScheme(), id.getId(), Long.toHexString(cnxn.getSessionId()), cnxn.getHostAddress()); } }); }