ZOOKEEPER-4922: Audit JAAS login, logout and Kerberos ticket renewal

zookeeper-server/src/main/java/org/apache/zookeeper/Login.java

@@ -37,6 +37,9 @@
 import javax.security.auth.login.Configuration;
 import javax.security.auth.login.LoginContext;
 import javax.security.auth.login.LoginException;
+import org.apache.zookeeper.audit.AuditConstants;
+import org.apache.zookeeper.audit.AuditEvent.Result;
+import org.apache.zookeeper.audit.ZKAuditProvider;
 import org.apache.zookeeper.client.ZKClientConfig;
 import org.apache.zookeeper.common.Time;
 import org.apache.zookeeper.common.ZKConfig;
@@ -81,7 +84,8 @@ public class Login {
 
     private LoginContext login = null;
     private String loginContextName = null;
-    private String principal = null;
+    private final String principal;
+    private volatile String auditPrincipal = SYSTEM_USER;
 
     // Initialize 'lastLogin' to do a login at first time
     private long lastLogin = Time.currentElapsedTime() - MIN_TIME_BEFORE_RELOGIN;
@@ -106,24 +110,11 @@ public class Login {
     public Login(final String loginContextName, Supplier<CallbackHandler> callbackHandlerSupplier, final ZKConfig zkConfig) throws LoginException {
         this.zkConfig = zkConfig;
         this.callbackHandlerSupplier = callbackHandlerSupplier;
+        principal = readLoginConfiguration(loginContextName);
         login = login(loginContextName);
         this.loginContextName = loginContextName;
         subject = login.getSubject();
         isKrbTicket = !subject.getPrivateCredentials(KerberosTicket.class).isEmpty();
-        AppConfigurationEntry[] entries = Configuration.getConfiguration().getAppConfigurationEntry(loginContextName);
-        for (AppConfigurationEntry entry : entries) {
-            // there will only be a single entry, so this for() loop will only be iterated through once.
-            if (entry.getOptions().get("useTicketCache") != null) {
-                String val = (String) entry.getOptions().get("useTicketCache");
-                if (val.equals("true")) {
-                    isUsingTicketCache = true;
-                }
-            }
-            if (entry.getOptions().get("principal") != null) {
-                principal = (String) entry.getOptions().get("principal");
-            }
-            break;
-        }
 
         if (!isKrbTicket) {
             // if no TGT, do not bother with ticket management.
@@ -228,6 +219,7 @@ public void run() {
                                 Shell.execCommand(cmd, kinitArgs);
                                 break;
                             } catch (Exception e) {
+                                audit(getAuditUser(subject), AuditConstants.OP_TICKET_RENEWAL, Result.FAILURE);
                                 if (retry > 0) {
                                     --retry;
                                     // sleep for 10 seconds
@@ -330,17 +322,86 @@ public String getLoginContextName() {
     }
 
     private synchronized LoginContext login(final String loginContextName) throws LoginException {
+        try {
+            if (loginContextName == null) {
+                throw new LoginException("loginContext name (JAAS file section header) was null. "
+                                         + "Please check your java.security.login.auth.config (="
+                                         + System.getProperty("java.security.login.auth.config")
+                                         + ") and your "
+                                         + getLoginContextMessage());
+            }
+            LoginContext loginContext = new LoginContext(loginContextName, newCallbackHandler());
+            loginContext.login();
+            // Retain the authenticated identity even if a later logout clears the subject.
+            auditPrincipal = getAuditUser(loginContext.getSubject());
+            audit(auditPrincipal, AuditConstants.OP_LOGIN, Result.SUCCESS);
+            LOG.info("{} successfully logged in.", loginContextName);
+            return loginContext;
+        } catch (LoginException e) {
+            audit(auditPrincipal, AuditConstants.OP_LOGIN, Result.FAILURE);
+            throw e;
+        }
+    }
+
+    private String readLoginConfiguration(String loginContextName) {
         if (loginContextName == null) {
-            throw new LoginException("loginContext name (JAAS file section header) was null. "
-                                     + "Please check your java.security.login.auth.config (="
-                                     + System.getProperty("java.security.login.auth.config")
-                                     + ") and your "
-                                     + getLoginContextMessage());
+            return null;
+        }
+        // LoginContext falls back to "other" when the named configuration is absent.
+        Configuration configuration = Configuration.getConfiguration();
+        AppConfigurationEntry[] entries = configuration.getAppConfigurationEntry(loginContextName);
+        if (entries == null) {
+            entries = configuration.getAppConfigurationEntry("other");
+        }
+        if (entries != null && entries.length > 0) {
+            AppConfigurationEntry entry = entries[0];
+            isUsingTicketCache = "true".equals(entry.getOptions().get("useTicketCache"));
+            Object principalOption = entry.getOptions().get("principal");
+            String configuredUser = null;
+            // A Kerberos module can follow other modules in the JAAS chain.
+            for (AppConfigurationEntry configuredEntry : entries) {
+                Object configuredValue = configuredEntry.getOptions().get("principal");
+                if (configuredValue instanceof String configuredPrincipal && !configuredPrincipal.isEmpty()) {
+                    configuredUser = configuredPrincipal;
+                    break;
+                }
+                Object username = configuredEntry.getOptions().get("username");
+                if (configuredUser == null && username instanceof String && !((String) username).isEmpty()) {
+                    configuredUser = (String) username;
+                }
+            }
+            if (configuredUser != null) {
+                auditPrincipal = configuredUser;
+            }
+            return principalOption instanceof String ? (String) principalOption : null;
+        }
+        return null;
+    }
+
+    private String getAuditUser(Subject loginSubject) {
+        if (loginSubject != null) {
+            for (KerberosPrincipal kerberosPrincipal : loginSubject.getPrincipals(KerberosPrincipal.class)) {
+                return kerberosPrincipal.getName();
+            }
+            // SecurityUtils uses the public credential as the DIGEST-MD5 username.
+            for (String username : loginSubject.getPublicCredentials(String.class)) {
+                if (!username.isEmpty()) {
+                    return username;
+                }
+            }
+        }
+        return auditPrincipal;
+    }
+
+    private void audit(String user, String operation, Result result) {
+        try {
+            // An early client must not freeze audit configuration while auditing is disabled.
+            if (Boolean.getBoolean(ZKAuditProvider.AUDIT_ENABLE)) {
+                ZKAuditProvider.log(user, operation, result);
+            }
+        } catch (RuntimeException | LinkageError e) {
+            LOG.error("Unable to audit {} ({}) for {}", operation, result, user, e);
         }
-        LoginContext loginContext = new LoginContext(loginContextName, newCallbackHandler());
-        loginContext.login();
-        LOG.info("{} successfully logged in.", loginContextName);
-        return loginContext;
     }
 
     private String getLoginContextMessage() {
@@ -387,7 +448,7 @@ private synchronized KerberosTicket getTGT() {
         return null;
     }
 
-    private boolean hasSufficientTimeElapsed() {
+    private boolean tryBeginReLogin() {
         long now = Time.currentElapsedTime();
         if (now - getLastLogin() < MIN_TIME_BEFORE_RELOGIN) {
             LOG.warn("Not attempting to re-login since the last re-login was "
@@ -437,29 +498,32 @@ public long getLastLogin() {
      * @throws javax.security.auth.login.LoginException on a failure
      */
     // c.f. HADOOP-6559
-    private synchronized void reLogin() throws LoginException {
+    synchronized void reLogin() throws LoginException {
         if (!isKrbTicket) {
             return;
         }
         LoginContext login = getLogin();
         if (login == null) {
             throw new LoginException("login must be done first");
         }
-        if (!hasSufficientTimeElapsed()) {
+        if (!tryBeginReLogin()) {
             return;
         }
+        String user = getAuditUser(subject);
         LOG.info("Initiating logout for {}", principal);
         synchronized (Login.class) {
-            //clear up the kerberos state. But the tokens are not cleared! As per
-            //the Java kerberos login module code, only the kerberos credentials
-            //are cleared
-            logout();
-            //login and also update the subject field of this instance to
-            //have the new credentials (pass it to the LoginContext constructor)
-            login = new LoginContext(loginContextName, getSubject());
-            LOG.info("Initiating re-login for {}", principal);
-            login.login();
-            setLogin(login);
+            try {
+                logout();
+                login = new LoginContext(loginContextName, getSubject());
+                LOG.info("Initiating re-login for {}", principal);
+                login.login();
+                setLogin(login);
+                auditPrincipal = getAuditUser(login.getSubject());
+                audit(auditPrincipal, AuditConstants.OP_TICKET_RENEWAL, Result.SUCCESS);
+            } catch (LoginException e) {
+                audit(user, AuditConstants.OP_TICKET_RENEWAL, Result.FAILURE);
+                throw e;
+            }
         }
     }
 
@@ -469,7 +533,14 @@ protected synchronized void logout() throws LoginException {
         // are not logged in. Since Java 9 this could result in an NPE.
         // See ZOOKEEPER-4477 for more details.
         if (subject != null && !subject.getPrincipals().isEmpty()) {
-            login.logout();
+            String user = getAuditUser(subject);
+            try {
+                login.logout();
+                audit(user, AuditConstants.OP_LOGOUT, Result.SUCCESS);
+            } catch (LoginException e) {
+                audit(user, AuditConstants.OP_LOGOUT, Result.FAILURE);
+                throw e;
+            }
         }
     }
 

zookeeper-server/src/main/java/org/apache/zookeeper/audit/AuditConstants.java

@@ -24,6 +24,9 @@ private AuditConstants() {
 
     static final String OP_START = "serverStart";
     static final String OP_STOP = "serverStop";
+    public static final String OP_LOGIN = "login";
+    public static final String OP_LOGOUT = "logout";
+    public static final String OP_TICKET_RENEWAL = "ticketRenewal";
     public static final String OP_CREATE = "create";
     public static final String OP_DELETE = "delete";
     public static final String OP_SETDATA = "setData";

zookeeper-server/src/main/java/org/apache/zookeeper/audit/ZKAuditProvider.java

@@ -25,29 +25,60 @@
 import org.slf4j.LoggerFactory;
 
 public class ZKAuditProvider {
-    static final String AUDIT_ENABLE = "zookeeper.audit.enable";
+    /**
+     * System property that enables audit logging.
+     */
+    public static final String AUDIT_ENABLE = "zookeeper.audit.enable";
     static final String AUDIT_IMPL_CLASS = "zookeeper.audit.impl.class";
     private static final Logger LOG = LoggerFactory.getLogger(ZKAuditProvider.class);
-    // By default audit logging is disabled
-    private static boolean auditEnabled;
-    private static AuditLogger auditLogger;
-
-    static {
-        auditEnabled = Boolean.getBoolean(AUDIT_ENABLE);
-        if (auditEnabled) {
-            //initialise only when audit logging is enabled
-            auditLogger = getAuditLogger();
-            LOG.info("ZooKeeper audit is enabled.");
-        } else {
-            LOG.info("ZooKeeper audit is disabled.");
+    private static String selectedAuditLoggerClass;
+
+    // Parsing server configuration must not initialize the audit logger.
+    private static class AuditState {
+        private static final boolean auditEnabled;
+        private static final AuditLogger auditLogger;
+        private static final RuntimeException initializationFailure;
+
+        static {
+            String loggerClass = null;
+            synchronized (ZKAuditProvider.class) {
+                auditEnabled = Boolean.getBoolean(AUDIT_ENABLE);
+                if (auditEnabled) {
+                    loggerClass = System.getProperty(AUDIT_IMPL_CLASS, Slf4jAuditLogger.class.getName());
+                    selectedAuditLoggerClass = loggerClass;
+                }
+            }
+            AuditLogger logger = null;
+            RuntimeException failure = null;
+            if (auditEnabled) {
+                try {
+                    logger = getAuditLogger(loggerClass);
+                    LOG.info("ZooKeeper audit is enabled.");
+                } catch (RuntimeException | LinkageError e) {
+                    failure = new IllegalStateException("Couldn't initialize audit logger " + loggerClass, e);
+                }
+            } else {
+                LOG.info("ZooKeeper audit is disabled.");
+            }
+            auditLogger = logger;
+            initializationFailure = failure;
         }
     }
 
-    private static AuditLogger getAuditLogger() {
-        String auditLoggerClass = System.getProperty(AUDIT_IMPL_CLASS);
-        if (auditLoggerClass == null) {
-            auditLoggerClass = Slf4jAuditLogger.class.getName();
+    /**
+     * Configures the audit logger class without initializing the logger.
+     *
+     * @throws IllegalArgumentException if another audit logger class has already been selected
+     */
+    public static synchronized void configureAuditLogger(String loggerClass) {
+        if (selectedAuditLoggerClass != null && !selectedAuditLoggerClass.equals(loggerClass)) {
+            throw new IllegalArgumentException("Audit logger is already selected as " + selectedAuditLoggerClass
+                + "; cannot configure " + loggerClass + ". Set " + AUDIT_IMPL_CLASS + " before using the audit provider.");
         }
+        System.setProperty(AUDIT_IMPL_CLASS, loggerClass);
+    }
+
+    private static AuditLogger getAuditLogger(String auditLoggerClass) {
         try {
             Constructor<?> clientCxnConstructor = Class.forName(auditLoggerClass)
                     .getDeclaredConstructor();
@@ -60,15 +91,29 @@ private static AuditLogger getAuditLogger() {
     }
 
     /**
-     * @return true if audit log is enabled
+     * Initializes the audit state and reports any logger initialization failure.
+     *
+     * @throws IllegalStateException if the audit logger could not be initialized
+     */
+    public static void checkAuditState() {
+        if (AuditState.initializationFailure != null) {
+            throw AuditState.initializationFailure;
+        }
+    }
+
+    /**
+     * @return true if audit logging is configured as enabled
      */
     public static boolean isAuditEnabled() {
-        return auditEnabled;
+        return AuditState.auditEnabled;
     }
 
     public static void log(String user, String operation, String znode, String acl,
                            String createMode, String session, String ip, Result result) {
-        auditLogger.logAuditEvent(createLogEvent(user, operation, znode, acl, createMode, session, ip, result));
+        if (isAuditEnabled()) {
+            checkAuditState();
+            AuditState.auditLogger.logAuditEvent(createLogEvent(user, operation, znode, acl, createMode, session, ip, result));
+        }
     }
 
     /**
@@ -111,15 +156,26 @@ public static void addZKStartStopAuditLog() {
 
     /**
      * Add audit log for server start fail.
+     * Audit errors must not prevent the server from exiting with its intended code.
      */
     public static void addServerStartFailureAuditLog() {
-        if (isAuditEnabled()) {
-            log(ZKAuditProvider.getZKUser(), AuditConstants.OP_START, Result.FAILURE);
+        try {
+            if (isAuditEnabled()) {
+                log(ZKAuditProvider.getZKUser(), AuditConstants.OP_START, Result.FAILURE);
+            }
+        } catch (RuntimeException | LinkageError e) {
+            LOG.error("Unable to audit server startup failure", e);
         }
     }
 
-    private static void log(String user, String operation, Result result) {
-        auditLogger.logAuditEvent(createLogEvent(user, operation, result));
+    /**
+     * Logs an operation without session, IP, or znode fields when auditing is enabled.
+     */
+    public static void log(String user, String operation, Result result) {
+        if (isAuditEnabled()) {
+            checkAuditState();
+            AuditState.auditLogger.logAuditEvent(createLogEvent(user, operation, result));
+        }
     }
 
     /**

zookeeper-server/src/main/java/org/apache/zookeeper/server/ZooKeeperServerMain.java

@@ -119,6 +119,8 @@ protected void initializeAndRun(String[] args) throws ConfigException, IOExcepti
      * @throws AdminServerException
      */
     public void runFromConfig(ServerConfig config) throws IOException, AdminServerException {
+        // Validate auditing before starting metrics, transaction storage, or listeners.
+        ZKAuditProvider.checkAuditState();
         LOG.info("Starting server");
         FileTxnSnapLog txnLog = null;
         try {

zookeeper-server/src/main/java/org/apache/zookeeper/server/embedded/ZooKeeperServerEmbeddedImpl.java

@@ -10,6 +10,7 @@
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.TimeoutException;
 import javax.security.sasl.SaslException;
+import org.apache.zookeeper.audit.ZKAuditProvider;
 import org.apache.zookeeper.server.DatadirCleanupManager;
 import org.apache.zookeeper.server.ExitCode;
 import org.apache.zookeeper.server.ServerConfig;
@@ -85,6 +86,8 @@ public void start() throws Exception {
 
     @Override
     public void start(long startupTimeout) throws Exception {
+        // Validate before scheduling purge or starting the server thread.
+        ZKAuditProvider.checkAuditState();
         switch (exitHandler) {
             case EXIT:
                 ServiceUtils.setSystemExitProcedure(ServiceUtils.SYSTEM_EXIT);