REPO-3884: DBP SSO: Sufficient logging (#36)

src/main/java/org/alfresco/repo/security/authentication/AlfrescoSecureContextImpl.java

@@ -27,6 +27,8 @@ package org.alfresco.repo.security.authentication;
 
 import net.sf.acegisecurity.Authentication;
 import net.sf.acegisecurity.context.ContextInvalidException;
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
 
 /**
  * Hold an Alfresco extended security context
@@ -36,6 +38,8 @@ import net.sf.acegisecurity.context.ContextInvalidException;
  */
 public class AlfrescoSecureContextImpl implements AlfrescoSecureContext
 {
+    Log logger = LogFactory.getLog(getClass());
+
     private static final long serialVersionUID = -8893133731693272549L;
 
     private Authentication realAuthentication;
@@ -81,11 +85,19 @@ public class AlfrescoSecureContextImpl implements AlfrescoSecureContext
 
     public void setEffectiveAuthentication(Authentication effictiveAuthentication)
     {
+        if (logger.isTraceEnabled())
+        {
+            logger.trace("Setting effective authentication to: " + AuthenticationUtil.getMaskedUsername(effictiveAuthentication));
+        }
         this.effectiveAuthentication = effictiveAuthentication;
     }
 
     public void setRealAuthentication(Authentication realAuthentication)
     {
+        if (logger.isTraceEnabled())
+        {
+            logger.trace("Setting real authentication to: " + AuthenticationUtil.getMaskedUsername(realAuthentication));
+        }
         this.realAuthentication = realAuthentication;
     }
 
@@ -133,21 +145,21 @@ public class AlfrescoSecureContextImpl implements AlfrescoSecureContext
 
         if (realAuthentication == null)
         {
-            builder.append("Real authenticaion = null");
+            builder.append("Real authentication = null");
         }
         else
         {
-            builder.append("Real authenticaion = " + realAuthentication.toString());
+            builder.append("Real authentication = " + AuthenticationUtil.getMaskedUsername(realAuthentication));
         }
         builder.append(", ");
         
         if (effectiveAuthentication == null)
         {
-            builder.append("Effective authenticaion = null");
+            builder.append("Effective authentication = null");
         }
         else
         {
-            builder.append("Effective authenticaion = " + effectiveAuthentication.toString());
+            builder.append("Effective authentication = " +AuthenticationUtil.getMaskedUsername(effectiveAuthentication));
         }
         builder.append(", ");
         

src/main/java/org/alfresco/repo/security/authentication/AuthenticationUtil.java

@@ -54,7 +54,7 @@ import org.springframework.beans.factory.InitializingBean;
 @AlfrescoPublicApi
 public class AuthenticationUtil implements InitializingBean
 {
-    static Log s_logger = LogFactory.getLog(AuthenticationUtil.class);
+    static Log logger = LogFactory.getLog(AuthenticationUtil.class);
     @AlfrescoPublicApi
     public interface RunAsWork<Result>
     {
@@ -94,8 +94,10 @@ public class AuthenticationUtil implements InitializingBean
     
     public static void setMtEnabled(boolean mtEnabled)
     {
-        if (s_logger.isDebugEnabled())
+        if (logger.isDebugEnabled())
-            s_logger.debug("MT is enabled: " + mtEnabled);
+        {
+            logger.debug("MT is enabled: " + mtEnabled);
+        }
         AuthenticationUtil.mtEnabled = mtEnabled;
     }
 
@@ -104,6 +106,39 @@ public class AuthenticationUtil implements InitializingBean
         return AuthenticationUtil.mtEnabled;
     }
 
+    public static String maskUsername(String userName)
+    {
+        if (userName != null)
+        {
+            try
+            {
+                if (userName.length() >= 2)
+                {
+                    return userName.substring(0, 2) + new String(new char[(userName.length() - 2)]).replace("\0", "*");
+                }
+            }
+            catch (Exception e)
+            {
+                if (logger.isDebugEnabled())
+                {
+                    logger.debug("Failed to mask the username because: " + e.getMessage(), e);
+                }
+            }
+            return userName;
+        }
+        return null;
+    }
+
+    public static String getMaskedUsername(Authentication authentication)
+    {
+        String extractedUsername = null;
+        if (authentication != null && authentication.getPrincipal() != null)
+        {
+            extractedUsername = getUserName(authentication);
+        }
+        return maskUsername(extractedUsername);
+    }
+
     public AuthenticationUtil()
     {
         super();
@@ -231,16 +266,20 @@ public class AuthenticationUtil implements InitializingBean
         }
         else
         {
-            if (s_logger.isDebugEnabled())
+            if (logger.isTraceEnabled())
-                s_logger.debug("Setting fully authenticated principal: " + authentication.getName());
+            {
+                logger.trace("Setting fully authenticated principal: " + getMaskedUsername(authentication));
+            }
             Context context = ContextHolder.getContext();
             AlfrescoSecureContext sc = null;
             if ((context == null) || !(context instanceof AlfrescoSecureContext))
             {
-                if (s_logger.isDebugEnabled())
-                    s_logger.debug("Creating new secure context.");
                 sc = new AlfrescoSecureContextImpl();
                 ContextHolder.setContext(sc);
+                if (logger.isTraceEnabled())
+                {
+                    logger.trace("Setting new secure context: " + sc + " on thread: " + Thread.currentThread().getName());
+                }
             }
             else
             {
@@ -307,16 +346,20 @@ public class AuthenticationUtil implements InitializingBean
         }
         else
         {
-            if (s_logger.isDebugEnabled())
+            if (logger.isTraceEnabled())
-                s_logger.debug("Setting RunAs principal: " + authentication.getName());
+            {
+                logger.trace("Setting RunAs principal: " + getMaskedUsername(authentication));
+            }
             Context context = ContextHolder.getContext();
             AlfrescoSecureContext sc = null;
             if ((context == null) || !(context instanceof AlfrescoSecureContext))
             {
-                if (s_logger.isDebugEnabled())
-                    s_logger.debug("Creating new secure context.");
                 sc = new AlfrescoSecureContextImpl();
                 ContextHolder.setContext(sc);
+                if (logger.isTraceEnabled())
+                {
+                    logger.trace("Setting new secure context: " + sc + " on thread: " + Thread.currentThread().getName());
+                }
             }
             else
             {
@@ -325,8 +368,10 @@ public class AuthenticationUtil implements InitializingBean
             authentication.setAuthenticated(true);
             if (sc.getRealAuthentication() == null)
             {
-                if (s_logger.isDebugEnabled())
+                if (logger.isTraceEnabled())
-                    s_logger.debug("There is no fully authenticated prinipal. Setting fully authenticated principal: " + authentication.getName());
+                {
+                    logger.trace("There is no fully authenticated principal. Setting fully authenticated principal: " + getMaskedUsername(authentication));
+                }
                 sc.setRealAuthentication(authentication);
             }
             sc.setEffectiveAuthentication(authentication);
@@ -500,8 +545,10 @@ public class AuthenticationUtil implements InitializingBean
      */
     public static void clearCurrentSecurityContext()
     {
-        if (s_logger.isDebugEnabled())
+        if (logger.isTraceEnabled())
-            s_logger.debug("Removing the current security information.");
+        {
+            logger.trace("Removing the current security information for thread: " + Thread.currentThread().getName());
+        }
         ContextHolder.setContext(null);
         InMemoryTicketComponentImpl.clearCurrentSecurityContext();
         
@@ -624,6 +671,10 @@ public class AuthenticationUtil implements InitializingBean
         threadLocalRunAsAuthenticationStack.get().push(originalRunAsAuthentication);
         
         threadLocalTenantDomainStack.get().push(TenantContextHolder.getTenantDomain());
+        if (logger.isTraceEnabled())
+        {
+            logger.trace("Pushed authentication in thread: " + Thread.currentThread().getName());
+        }
     }
     
     /**
@@ -646,6 +697,10 @@ public class AuthenticationUtil implements InitializingBean
         
         String originalTenantDomain = threadLocalTenantDomainStack.get().pop();
         TenantContextHolder.setTenantDomain(originalTenantDomain);
+        if (logger.isTraceEnabled())
+        {
+            logger.trace("Popped authentication in thread: " + Thread.currentThread().getName());
+        }
     }
 
     /**
@@ -653,12 +708,12 @@ public class AuthenticationUtil implements InitializingBean
      */
     public static void logAuthenticatedUsers()
     {
-        if (s_logger.isDebugEnabled())
+        if (logger.isDebugEnabled())
         {
-            s_logger.debug(
+            logger.debug(
                     "Authentication: \n" +
-                    "   Fully authenticated: " + AuthenticationUtil.getFullyAuthenticatedUser() + "\n" +
+                    "   Fully authenticated: " + maskUsername(getFullyAuthenticatedUser()) + "\n" +
-                    "   Run as:              " + AuthenticationUtil.getRunAsUser());
+                    "   Run as:              " + maskUsername(getRunAsUser()));
         }
     }
 
@@ -675,16 +730,16 @@ public class AuthenticationUtil implements InitializingBean
                 final String tenantDomain = userTenant.getSecond();
                 if (! TenantService.DEFAULT_DOMAIN.equals(tenantDomain))
                 {
-                    NDC.push("Tenant:" +tenantDomain + " User:" + userName);
+                    NDC.push("Tenant:" +tenantDomain + " User:" + maskUsername(userName));
                 }
                 else
                 {
-                    NDC.push("User:" + userName);
+                    NDC.push("User:" + maskUsername(userName));
                 }
             }
             else
             {
-                NDC.push("User:" + userNameIn);
+                NDC.push("User:" + maskUsername(userNameIn));
             }
         }
     }
@@ -712,9 +767,9 @@ public class AuthenticationUtil implements InitializingBean
                         throw new AlfrescoRuntimeException("Unexpected tenant: "+tenantDomain+" (contains @)");
                     }
 
-                    if (s_logger.isDebugEnabled())
+                    if (logger.isDebugEnabled())
                     {
-                        s_logger.debug("Tenant domain implied: userName="+userName+", tenantDomain="+tenantDomain);
+                        logger.debug("Tenant domain implied: userName=" + maskUsername(userName) + ", tenantDomain=" + tenantDomain);
                     }
                 }
             }

src/main/java/org/alfresco/repo/security/authentication/InMemoryTicketComponentImpl.java

@@ -53,7 +53,7 @@ public class InMemoryTicketComponentImpl implements TicketComponent
      */
     public static final String GRANTED_AUTHORITY_TICKET_PREFIX = "TICKET_";
 
-    Log logger = LogFactory.getLog(getClass());
+    private static Log logger = LogFactory.getLog(InMemoryTicketComponentImpl.class);
 
     private static ThreadLocal<String> currentTicket = new ThreadLocal<String>();
     private boolean ticketsExpire;
@@ -157,6 +157,10 @@ public class InMemoryTicketComponentImpl implements TicketComponent
       
         String ticketString = GRANTED_AUTHORITY_TICKET_PREFIX + ticket.getTicketId();
         currentTicket.set(ticketString);
+        if (logger.isTraceEnabled())
+        {
+            logger.trace("Setting the current ticket for this thread: " + Thread.currentThread().getName() + " to: " + ticketString);
+        }
         return ticketString;
     }
 
@@ -187,16 +191,30 @@ public class InMemoryTicketComponentImpl implements TicketComponent
     @Override
     public String validateTicket(String ticketString) throws AuthenticationException
     {
+        if (logger.isTraceEnabled())
+        {
+            logger.trace("Validating ticket: " + ticketString);
+        }
         String ticketKey = getTicketKey(ticketString);
         Ticket ticket = ticketsCache.get(ticketKey);
         if (ticket == null)
         {
-            throw new AuthenticationException("Missing ticket for " + ticketString);
+            final String msg = "Missing ticket for " + ticketString;
+            if (logger.isDebugEnabled())
+            {
+                logger.debug(msg);
+            }
+            throw new AuthenticationException(msg);
         }
         Ticket newTicket = ticket.getNewEntry();
         if (newTicket == null)
         {
-            throw new TicketExpiredException("Ticket expired for " + ticketString);
+            final String msg = "Ticket expired for " + ticketString;
+            if (logger.isDebugEnabled())
+            {
+                logger.debug(msg);
+            }
+            throw new TicketExpiredException(msg);
         }
         if (oneOff)
         {
@@ -208,6 +226,10 @@ public class InMemoryTicketComponentImpl implements TicketComponent
             ticketsCache.put(ticketKey, newTicket);
         }
         currentTicket.set(ticketString);
+        if (logger.isTraceEnabled())
+        {
+            logger.trace("Setting the current ticket for this thread: " + Thread.currentThread().getName() + " to: " + ticketString);
+        }
         return newTicket.getUserName();
     }
 
@@ -247,6 +269,10 @@ public class InMemoryTicketComponentImpl implements TicketComponent
     @Override
     public void invalidateTicketById(String ticketString)
     {
+        if (logger.isTraceEnabled())
+        {
+            logger.trace("Invalidate ticket: " + ticketString);
+        }
         String key = ticketString.substring(GRANTED_AUTHORITY_TICKET_PREFIX.length());
         ticketsCache.remove(key);
     }
@@ -296,6 +322,10 @@ public class InMemoryTicketComponentImpl implements TicketComponent
     @Override
     public int invalidateTickets(boolean expiredOnly)
     {
+        if (logger.isTraceEnabled())
+        {
+            logger.trace("Invalidate all tickets, expired only: " + expiredOnly);
+        }
         Date now = new Date();
         int count = 0;
         if (!expiredOnly)
@@ -345,6 +375,10 @@ public class InMemoryTicketComponentImpl implements TicketComponent
         for (String id : toRemove)
         {
             ticketsCache.remove(id);
+            if (logger.isTraceEnabled())
+            {
+                logger.trace("Invalidate ticket for username: " + AuthenticationUtil.maskUsername(userName) + " ticket: " + id);
+            }
         }
     }
 
@@ -440,6 +474,10 @@ public class InMemoryTicketComponentImpl implements TicketComponent
                 }
             }
             this.ticketId = ticketId;
+            if (logger.isTraceEnabled())
+            {
+                logger.trace("Creating new ticket for user:" + AuthenticationUtil.maskUsername(userName));
+            }
         }
 
         private Ticket(ExpiryMode expires, Date expiryDate, String userName, Duration validDuration, String ticketId)
@@ -451,6 +489,10 @@ public class InMemoryTicketComponentImpl implements TicketComponent
             Duration tenPercent = validDuration.divide(10);
             this.testDuration = validDuration.subtract(tenPercent);
             this.ticketId = ticketId;
+            if (logger.isTraceEnabled())
+            {
+                logger.trace("Creating new ticket for user:" + AuthenticationUtil.maskUsername(userName));
+            }
         }
         
         boolean hasExpired(Date now)
@@ -483,6 +525,10 @@ public class InMemoryTicketComponentImpl implements TicketComponent
                     Duration remaining = new Duration(now, expiryDate);
                     if(remaining.compareTo(testDuration) < 0)
                     {
+                        if (logger.isTraceEnabled())
+                        {
+                            logger.trace("AFTER_INACTIVITY case, Creating new ticket based on the current one that expires at: " + expiryDate);
+                        }
                         return new Ticket(expires, Duration.add(now, validDuration), userName, validDuration, ticketId);
                     }
                     else
@@ -575,7 +621,12 @@ public class InMemoryTicketComponentImpl implements TicketComponent
 
     public static void clearCurrentSecurityContext()
     {
+        String prevTicket = currentTicket.get();
         currentTicket.set(null);
+        if (logger.isTraceEnabled())
+        {
+            logger.trace("Clearing the current ticket for this thread: " + Thread.currentThread().getName() + " . Previous ticket was: " + prevTicket);
+        }
     }
 
     public enum ExpiryMode