HPCC-20111 LDAP Managed Scope cache improvements

The refresh of the cache that holds the names of all scopes managed by LDAP
can thrash when multiple threads hit the same refresh logic. Need to
serialize the refresh of the Managed File Scopes cache. Also some minor
improvements to the debug trace logic

Signed-off-by: Russ Whitehead <william.whitehead@lexisnexis.com>

system/security/shared/caching.cpp

@@ -524,25 +524,31 @@ inline void CPermissionsCache::removeAllManagedFileScopes()
 
     etc. Until full scope path checked, or no read permissions hit on ancestor scope.
 */
+static CriticalSection msCacheSyncCS;//for managed scopes cache syncronization
 bool CPermissionsCache::queryPermsManagedFileScope(ISecUser& sec_user, const char * fullScope, StringBuffer& managedScope, SecAccessFlags * accessFlags)
 {
+    unsigned start = msTick();
     if (!fullScope || !*fullScope)
     {
         *accessFlags = queryDefaultPermission(sec_user);
         return true;
     }
 
-    time_t now;
-    time(&now);
-    if (m_secMgr && (0 == m_lastManagedFileScopesRefresh || m_lastManagedFileScopesRefresh < (now - m_cacheTimeout)))
+    if (m_secMgr)
     {
-        removeAllManagedFileScopes();
-        IArrayOf<ISecResource> scopes;
-        aindex_t count = m_secMgr->getManagedFileScopes(scopes);
-        if (count)
-            addManagedFileScopes(scopes);
-        m_defaultPermission = SecAccess_Unknown;//trigger refresh
-        m_lastManagedFileScopesRefresh = now;
+        CriticalBlock block(msCacheSyncCS);
+        time_t now;
+        time(&now);
+        if (0 == m_lastManagedFileScopesRefresh || ((now - m_lastManagedFileScopesRefresh) > m_cacheTimeout))
+        {
+            removeAllManagedFileScopes();
+            IArrayOf<ISecResource> scopes;
+            aindex_t count = m_secMgr->getManagedFileScopes(scopes);
+            if (count)
+                addManagedFileScopes(scopes);
+            m_defaultPermission = SecAccess_Unknown;//trigger refresh
+            time(&m_lastManagedFileScopesRefresh);
+        }
     }
 
     if (m_managedFileScopesMap.empty())
@@ -593,9 +599,7 @@ bool CPermissionsCache::queryPermsManagedFileScope(ISecUser& sec_user, const cha
                 {
                     *accessFlags = res->getAccessFlags();
                     managedScope.append(const_cast<char *>(res->getName()));
-#ifdef _DEBUG
-                    DBGLOG("FileScope %s for %s(%s) access denied %d",fullScope, sec_user.getName(), res->getName(), *accessFlags);
-#endif
+                    DBGLOG("FileScope %s for %s(%s) access denied %d at scope %s, took %dms",fullScope, sec_user.getName(), res->getName(), *accessFlags, scope, msTick()-start);
                     return true;
                 }
                 else
@@ -611,7 +615,7 @@ bool CPermissionsCache::queryPermsManagedFileScope(ISecUser& sec_user, const cha
             *accessFlags = matchedRes->getAccessFlags();
             managedScope.append(const_cast<char *>(matchedRes->getName()));
 #ifdef _DEBUG
-            DBGLOG("FileScope %s for %s(%s) access granted %d", fullScope, sec_user.getName(), matchedRes->getName(), *accessFlags);
+            DBGLOG("FileScope %s for %s(%s) access granted %d, took %dms", fullScope, sec_user.getName(), matchedRes->getName(), *accessFlags, msTick()-start);
 #endif
             rc = true;
         }
@@ -620,7 +624,7 @@ bool CPermissionsCache::queryPermsManagedFileScope(ISecUser& sec_user, const cha
             managedScope.append(const_cast<char *>(res->getName()));
 
 #ifdef _DEBUG
-            DBGLOG("FileScope %s for %s(%s) managed but not cached", fullScope, sec_user.getName(), res->getName());
+            DBGLOG("FileScope %s for %s(%s) managed but not cached, took %dms", fullScope, sec_user.getName(), res->getName(), msTick()-start);
 #endif
             rc = false;//need to go to LDAP to check
         }
@@ -629,7 +633,7 @@ bool CPermissionsCache::queryPermsManagedFileScope(ISecUser& sec_user, const cha
     {
         *accessFlags = queryDefaultPermission(sec_user);
 #ifdef _DEBUG
-        DBGLOG("FileScope %s for %s not managed, using default %d", fullScope, sec_user.getName(),*accessFlags);
+        DBGLOG("FileScope %s for %s not managed, using default %d, took %dms", fullScope, sec_user.getName(),*accessFlags, msTick()-start);
 #endif
         rc = true;
     }