Bug #1499: external acls are somewhat broken

by Gonzalo Arana

diff --git a/src/ACLChecklist.cc b/src/ACLChecklist.cc
index 6eeb87512ae10f064e89e2cd25665785d6e6ade9..d74000f49bbd73184698e14bd6c3cdfe5e5d71f9 100644 (file)
--- a/src/ACLChecklist.cc
+++ b/src/ACLChecklist.cc
@@ -1,5 +1,5 @@
 /*
- * $Id: ACLChecklist.cc,v 1.32 2006/04/02 11:58:38 serassio Exp $
+ * $Id: ACLChecklist.cc,v 1.33 2006/05/16 05:49:44 hno Exp $
  *
  * DEBUG: section 28    Access Control
  * AUTHOR: Duane Wessels
@@ -266,8 +266,21 @@ ACLChecklist::matchAclList(const acl_list * head, bool const fast)
 
         if (!nodeMatched || state_ != NullState::Instance()) {
             debug(28, 3) ("aclmatchAclList: %p returning false (AND list entry failed to match)\n", this);
+            bool async = state_ != NullState::Instance();
+
             checkForAsync();
 
+            bool async_in_progress = asyncInProgress();
+            debug(28,0)("aclmatchAclList: async=%d nodeMatched=%d async_in_progress=%d lastACLResult() = %d\n",
+                        async ? 1 : 0, nodeMatched ? 1 : 0, async_in_progress ? 1 : 0,
+                        lastACLResult() ? 1 : 0);
+
+            if (async && nodeMatched && !asyncInProgress() && lastACLResult()) {
+                // async acl, but using cached response, and it was a match
+                node = node->next;
+                continue;
+            }
+
             if (deleteWhenDone && !asyncInProgress())
                 delete this;
 
@@ -318,7 +331,8 @@ ACLChecklist::ACLChecklist() : accessList (NULL), my_port (0), request (NULL),
         allow_(ACCESS_DENIED),
         state_(NullState::Instance()),
         destinationDomainChecked_(false),
-        sourceDomainChecked_(false)
+        sourceDomainChecked_(false),
+        lastACLResult_(false)
 {
 
     memset (&src_addr, '\0', sizeof (struct IN_ADDR));

diff --git a/src/ACLChecklist.h b/src/ACLChecklist.h
index 0e4d4c470481e74e9657e9918c80ccec2fd4c1dc..671b7cf95ddbae298e0091cd04fc86faeeb0917c 100644 (file)
--- a/src/ACLChecklist.h
+++ b/src/ACLChecklist.h
@@ -1,6 +1,6 @@
 
 /*
- * $Id: ACLChecklist.h,v 1.22 2006/04/02 11:58:38 serassio Exp $
+ * $Id: ACLChecklist.h,v 1.23 2006/05/16 05:49:44 hno Exp $
  *
  *
  * SQUID Web Proxy Cache          http://www.squid-cache.org/
@@ -155,6 +155,13 @@ private:
     bool checking_;
     bool checking() const;
     void checking (bool const);
+
+    bool lastACLResult_;
+
+public:
+    bool lastACLResult(bool x) { return lastACLResult_ = x; }
+
+    bool lastACLResult() const { return lastACLResult_; }
 };
 
 SQUIDCEXTERN ACLChecklist *aclChecklistCreate(const acl_access *,

diff --git a/src/acl.cc b/src/acl.cc
index 759c1415682121ba24c4ae37552da7ad72388cff..7faffc2f443b156dc7771078f9dfaeaf575c2614 100644 (file)
--- a/src/acl.cc
+++ b/src/acl.cc
@@ -1,5 +1,5 @@
 /*
- * $Id: acl.cc,v 1.319 2006/04/25 12:00:29 robertc Exp $
+ * $Id: acl.cc,v 1.320 2006/05/16 05:49:44 hno Exp $
  *
  * DEBUG: section 28    Access Control
  * AUTHOR: Duane Wessels
@@ -300,11 +300,11 @@ ACLList::matches (ACLChecklist *checklist) const
 
     if (_acl->checklistMatches(checklist) != op) {
         debug(28,4)("ACLList::matches: result is false\n");
-        return false;
+        return checklist->lastACLResult(false);
     }
 
     debug(28,4)("ACLList::matches: result is true\n");
-    return true;
+    return checklist->lastACLResult(true);
 }
 
 

diff --git a/src/external_acl.cc b/src/external_acl.cc
index 3d0d320880821daea6f425fc9d08ede764e5d3ff..39c10ad19a3e43204b3b7bb44477a1cc7990132c 100644 (file)
--- a/src/external_acl.cc
+++ b/src/external_acl.cc
@@ -1,6 +1,6 @@
 
 /*
- * $Id: external_acl.cc,v 1.70 2006/05/08 23:38:33 robertc Exp $
+ * $Id: external_acl.cc,v 1.71 2006/05/16 05:49:44 hno Exp $
  *
  * DEBUG: section 82    External ACL
  * AUTHOR: Henrik Nordstrom, MARA Systems AB
@@ -659,10 +659,17 @@ aclMatchExternal(external_acl_data *acl, ACLChecklist * ch)
 
         if (!entry || external_acl_grace_expired(acl->def, entry)) {
             debug(82, 2) ("aclMatchExternal: %s(\"%s\") = lookup needed\n", acl->def->name, key);
+            debug(82, 2) ("aclMatchExternal: \"%s\": entry=@%p, age=%ld\n", key, entry,
+                          entry ? squid_curtime - entry->date : 0);
 
             if (acl->def->theHelper->stats.queue_size <= acl->def->theHelper->n_running) {
+                debug(82, 2) ("aclMatchExternal: \"%s\": queueing a call.\n", key);
                 ch->changeState (ExternalACLLookup::Instance());
-                return -1;
+
+                if (entry == NULL) {
+                    debug(82, 2) ("aclMatchExternal: \"%s\": return -1.\n", key);
+                    return -1;
+                }
             } else {
                 if (!entry) {
                     debug(82, 1) ("aclMatchExternal: '%s' queue overload. Request rejected '%s'.\n", acl->def->name, key);
@@ -1124,7 +1131,8 @@ ACLExternal::ExternalAclLookup(ACLChecklist * ch, ACLExternal * me, EAH * callba
         /* Make sure the user is authenticated */
 
         if ((ti = ch->authenticated()) != 1) {
-            debug(82, 1) ("externalAclLookup: %s user authentication failure (%d)\n", acl->def->name, ti);
+            debug(82, 1) ("externalAclLookup: %s user authentication failure (%d, ch=%p)\n",
+                          acl->def->name, ti, ch);
             callback(callback_data, NULL);
             return;
         }
@@ -1133,7 +1141,7 @@ ACLExternal::ExternalAclLookup(ACLChecklist * ch, ACLExternal * me, EAH * callba
     const char *key = makeExternalAclKey(ch, acl);
 
     if (!key) {
-        debug(82, 1) ("externalAclLookup: lookup in '%s', prerequisit failure\n", def->name);
+        debug(82, 1) ("externalAclLookup: lookup in '%s', prerequisit failure (ch=%p)\n", def->name, ch);
         callback(callback_data, NULL);
         return;
     }
@@ -1156,16 +1164,21 @@ ACLExternal::ExternalAclLookup(ACLChecklist * ch, ACLExternal * me, EAH * callba
 
     if (entry && external_acl_grace_expired(def, entry)) {
         if (oldstate) {
+            debug(82, 4) ("externalAclLookup: in grace period, but already pending lookup ('%s', ch=%p)\n",
+                          key, ch);
             callback(callback_data, entry);
             return;
         } else {
-            graceful = 1;
+            graceful = 1; // grace expired, (neg)ttl did not, and we must start a new lookup.
         }
     }
 
+    // The entry is in the cache, grace_ttl did not expired.
     if (!graceful && entry && !external_acl_grace_expired(def, entry)) {
         /* Should not really happen, but why not.. */
         callback(callback_data, entry);
+        debug(82, 4) ("externalAclLookup: no lookup pending for '%s', and grace not expired\n", key);
+        debug(82, 4) ("externalAclLookup: (what tha' hell?)\n");
         return;
     }
 
@@ -1189,7 +1202,7 @@ ACLExternal::ExternalAclLookup(ACLChecklist * ch, ACLExternal * me, EAH * callba
         /* Check for queue overload */
 
         if (def->theHelper->stats.queue_size >= def->theHelper->n_running) {
-            debug(82, 1) ("externalAclLookup: '%s' queue overload\n", def->name);
+            debug(82, 1) ("externalAclLookup: '%s' queue overload (ch=%p)\n", def->name, ch);
             cbdataFree(state);
             callback(callback_data, entry);
             return;
@@ -1200,6 +1213,8 @@ ACLExternal::ExternalAclLookup(ACLChecklist * ch, ACLExternal * me, EAH * callba
 
         buf.Printf("%s\n", key);
 
+        debug(82, 4) ("externalAclLookup: looking up for '%s' in '%s'.\n", key, def->name);
+
         helperSubmit(def->theHelper, buf.buf, externalAclHandleReply, state);
 
         dlinkAdd(state, &state->list, &def->queue);
@@ -1209,9 +1224,22 @@ ACLExternal::ExternalAclLookup(ACLChecklist * ch, ACLExternal * me, EAH * callba
 
     if (graceful) {
         /* No need to wait during grace period */
+        debug(82, 4) ("externalAclLookup: no need to wait for the result of '%s' in '%s' (ch=%p).\n",
+                      key, def->name, ch);
+        debug(82, 4) ("externalAclLookup: using cached entry %p\n", entry);
+
+        if (entry != NULL) {
+            debug(82,4) ("externalAclLookup: entry = { date=%lu, result=%d, user=%s tag=%s log=%s }\n",
+                         entry->date, entry->result, entry->user.buf(), entry->tag.buf(),
+                         entry->log.buf());
+        }
+
         callback(callback_data, entry);
         return;
     }
+
+    debug(82, 4) ("externalAclLookup: will wait for the result of '%s' in '%s' (ch=%p).\n",
+                  key, def->name, ch);
 }
 
 static void
@@ -1283,6 +1311,7 @@ ExternalACLLookup::checkForAsync(ACLChecklist *checklist)const
     /* TODO: optimise this - we probably have a pointer to this
      * around somewhere */
     ACL *acl = ACL::FindByName(AclMatchedName);
+    assert(acl);
     ACLExternal *me = dynamic_cast<ACLExternal *> (acl);
     assert (me);
     checklist->asyncInProgress(true);