Avoid reverse DNS lookups when logformat %>A is unused (#912)

Initially, the log_fqdn directive decided whether to do reverse DNS
lookups of client IP addresses ASAP, to improve our chances of logging
the resolved-by-then client FQDN.

Since commit 7684c4b, Squid started violating log_fqdn configuration,
enabling early reverse lookups if %>A was used in some logformat. Seven
years later, commit c581e96 completely removed the log_fqdn directive.

Unfortunately, the idea that seeing %>A somewhere means early lookups
are needed is flawed because

1. Some logformats containing %>A are never parsed. For example, the
   icap_squid logformat is still hard-coded as a printf()-based code.
   Using that format should enable early reverse lookups, but does not.

2. Some parsed logformats containing %>A may be unused. This is
   especially true for _default_ logformats that admins cannot control
   at all. Initially, no default logformats were parsed, but four years
   later, commit b11724b converted some hard-coded printf()s into parsed
   default logformats, inadvertently enabling reverse lookups in all
   Squid configurations!

   There is no way an admin could turn those lookups off because our
   DEFAULT: lines are parsed unconditionally; overwriting those defaults
   simply means that the corresponding logformat directive is parsed
   twice, once when parsing defaults (enabling the lookups) and then
   when parsing admin settings (the lookups state remains unchanged).

Transactions do not wait for these DNS lookup queries to be answered
and, due to DNS caching, not every client connection triggers a new DNS
query, but the total volume of these lookups may be significant in
environments with many client IP addresses, especially after a fresh
Squid start (or during a flash crowd arrival), when Squid DNS cache is
empty (or has not been primed with a lot of new addresses yet).

This change replaces the "parsed %>A enables early lookups" logic with
the "used %>A enables early lookups" approach. Logging of FQDNs is still
not guaranteed -- the lookups may not be enabled early enough and may
not complete by the time we use %>A -- but Squid instances not using %>A
are now guaranteed to avoid useless reverse DNS lookups of client IPs.

Also fixed logging of client FQDNs in the default ICAP access log format
(a.k.a. icap_squid): That format has the equivalent of a %>A field.
Thus, the icap_squid logging code must _always_ attempt to log FQDN and
enable early reverse DNS lookups. Neither was happening.

diff --git a/src/AccessLogEntry.cc b/src/AccessLogEntry.cc
index 58634e2c62cc24e5261054fbb4a54ff3afc0ebf6..4e4f0edc13607872ac2ca9b0b9fca35fdf6949b2 100644 (file)
--- a/src/AccessLogEntry.cc
+++ b/src/AccessLogEntry.cc
@@ -8,6 +8,7 @@
 
 #include "squid.h"
 #include "AccessLogEntry.h"
+#include "fqdncache.h"
 #include "HttpReply.h"
 #include "HttpRequest.h"
 #include "MemBuf.h"
@@ -46,6 +47,27 @@ AccessLogEntry::getLogClientIp(char *buf, size_t bufsz) const
     log_ip.toStr(buf, bufsz);
 }
 
+const char *
+AccessLogEntry::getLogClientFqdn(char * const buf, const size_t bufSize) const
+{
+    // TODO: Use indirect client and tcpClient like getLogClientIp() does.
+    const auto &client = cache.caddr;
+
+    // internally generated (and ICAP OPTIONS) requests lack client IP
+    if (client.isAnyAddr())
+        return "-";
+
+    // If we are here, Squid was configured to use %>A or equivalent.
+    // Improve our chances of getting FQDN by resolving client IPs ASAP.
+    Dns::ResolveClientAddressesAsap = true; // may already be true
+
+    // Too late for ours, but FQDN_LOOKUP_IF_MISS might help the next caller.
+    if (const auto fqdn = fqdncache_gethostbyaddr(client, FQDN_LOOKUP_IF_MISS))
+        return fqdn; // TODO: Return a safe SBuf from fqdncache_gethostbyaddr().
+
+    return client.toStr(buf, bufSize);
+}
+
 SBuf
 AccessLogEntry::getLogMethod() const
 {

diff --git a/src/AccessLogEntry.h b/src/AccessLogEntry.h
index d4b9cb9061b2a9197c8dc86feeac7820023e0042..abe9e56d769c971691574a3d51cbf0ca595693cf 100644 (file)
--- a/src/AccessLogEntry.h
+++ b/src/AccessLogEntry.h
@@ -55,6 +55,11 @@ public:
     /// including indirect forwarded-for IP if configured to log that
     void getLogClientIp(char *buf, size_t bufsz) const;
 
+    /// %>A: Compute client FQDN if possible, using the supplied buf if needed.
+    /// \returns result for immediate logging (not necessarily pointing to buf)
+    /// Side effect: Enables reverse DNS lookups of future client addresses.
+    const char *getLogClientFqdn(char *buf, size_t bufSize) const;
+
     /// Fetch the client IDENT string, or nil if none is available.
     const char *getClientIdent() const;
 

diff --git a/src/Makefile.am b/src/Makefile.am
index 38d731f2e30599c79477e0cf0a160d4f44214067..2fdbc3af00023dad69f7941115b43d0bb3b4f8ed 100644 (file)
--- a/src/Makefile.am
+++ b/src/Makefile.am
@@ -1100,6 +1100,7 @@ tests_testRock_SOURCES = \
        EventLoop.cc \
        FadingCounter.cc \
        FileMap.h \
+       tests/stub_fqdncache.cc \
        tests/stub_HelperChildConfig.cc \
        HttpBody.cc \
        HttpBody.h \
@@ -1274,6 +1275,7 @@ tests_testUfs_SOURCES = \
        EventLoop.cc \
        FadingCounter.cc \
        FileMap.h \
+       tests/stub_fqdncache.cc \
        tests/stub_HelperChildConfig.cc \
        HttpBody.cc \
        HttpBody.h \
@@ -1622,6 +1624,7 @@ tests_testDiskIO_SOURCES = \
        EventLoop.cc \
        FadingCounter.cc \
        FileMap.h \
+       tests/stub_fqdncache.cc \
        tests/stub_HelperChildConfig.cc \
        HttpBody.cc \
        HttpBody.h \

diff --git a/src/SquidConfig.h b/src/SquidConfig.h
index c25488a5676e62a3e560519e755804a4f2ed2b65..491dc98dba9630854794c216defef074ae959d60 100644 (file)
--- a/src/SquidConfig.h
+++ b/src/SquidConfig.h
@@ -289,7 +289,6 @@ public:
         int buffered_logs;
         int common_log;
         int log_mime_hdrs;
-        int log_fqdn;
         int announce;
         int mem_pools;
         int test_reachability;

diff --git a/src/cache_cf.cc b/src/cache_cf.cc
index 4b1773c3deb68161ba98e077969d1b3df1606a58..e14d81c8a3c9bbfe1bdac9ccc7f58e81bc04c3b4 100644 (file)
--- a/src/cache_cf.cc
+++ b/src/cache_cf.cc
@@ -33,6 +33,7 @@
 #include "eui/Config.h"
 #include "ExternalACL.h"
 #include "format/Format.h"
+#include "fqdncache.h"
 #include "ftp/Elements.h"
 #include "globals.h"
 #include "HttpHeaderTools.h"
@@ -3985,6 +3986,7 @@ void
 configFreeMemory(void)
 {
     free_all();
+    Dns::ResolveClientAddressesAsap = false;
     Config.ssl_client.sslContext.reset();
 #if USE_OPENSSL
     Ssl::unloadSquidUntrusted();

diff --git a/src/client_side.cc b/src/client_side.cc
index 04ffde1cc17880f1a981502782a2d343bcf23aaa..74128cbcf3e604dbd265d54e7df12107857b6927 100644 (file)
--- a/src/client_side.cc
+++ b/src/client_side.cc
@@ -2224,7 +2224,8 @@ ConnStateData::start()
 void
 ConnStateData::whenClientIpKnown()
 {
-    if (Config.onoff.log_fqdn)
+    debugs(33, 7, clientConnection->remote);
+    if (Dns::ResolveClientAddressesAsap)
         fqdncache_gethostbyaddr(clientConnection->remote, FQDN_LOOKUP_IF_MISS);
 
 #if USE_IDENT

diff --git a/src/format/Format.cc b/src/format/Format.cc
index 54f7d57c097114ec0366223553e081df7ca7404c..08c3ba2fe7f61957c09fff809e9fdd18e7473744 100644 (file)
--- a/src/format/Format.cc
+++ b/src/format/Format.cc
@@ -17,7 +17,6 @@
 #include "format/Format.h"
 #include "format/Quoting.h"
 #include "format/Token.h"
-#include "fqdncache.h"
 #include "http/Stream.h"
 #include "HttpRequest.h"
 #include "MemBuf.h"
@@ -410,14 +409,7 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             break;
 
         case LFT_CLIENT_FQDN:
-            if (al->cache.caddr.isAnyAddr()) // e.g., ICAP OPTIONS lack client
-                out = "-";
-            else
-                out = fqdncache_gethostbyaddr(al->cache.caddr, FQDN_LOOKUP_IF_MISS);
-
-            if (!out) {
-                out = al->cache.caddr.toStr(tmp, sizeof(tmp));
-            }
+            out = al->getLogClientFqdn(tmp, sizeof(tmp));
             break;
 
         case LFT_CLIENT_PORT:

diff --git a/src/format/Token.cc b/src/format/Token.cc
index 2f8dde8feb9ae3b17671a43e6eb2491acd0a014d..9d50af904235d681fd7892a7010abc3022804bde 100644 (file)
--- a/src/format/Token.cc
+++ b/src/format/Token.cc
@@ -593,10 +593,6 @@ Format::Token::parse(const char *def, Quoting *quoting)
 
         break;
 
-    case LFT_CLIENT_FQDN:
-        Config.onoff.log_fqdn = 1;
-        break;
-
     case LFT_TIME_TO_HANDLE_REQUEST:
     case LFT_PEER_RESPONSE_TIME:
     case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME:

diff --git a/src/fqdncache.cc b/src/fqdncache.cc
index fc0f7afe11cf5ac4f0665a9916751f3472b94322..ba0bccbd9529d8cd4f2f4c8bfac60a3b4f57ceef 100644 (file)
--- a/src/fqdncache.cc
+++ b/src/fqdncache.cc
@@ -28,6 +28,8 @@
 #include "snmp_core.h"
 #endif
 
+bool Dns::ResolveClientAddressesAsap = false;
+
 /**
  \defgroup FQDNCacheAPI FQDN Cache API
  \ingroup Components
@@ -484,6 +486,7 @@ fqdncache_gethostbyaddr(const Ip::Address &addr, int flags)
     fqdncache_entry *f = NULL;
 
     if (addr.isAnyAddr() || addr.isNoAddr()) {
+        debugs(35, 7, "nothing to lookup: " << addr);
         return NULL;
     }
 
@@ -497,10 +500,12 @@ fqdncache_gethostbyaddr(const Ip::Address &addr, int flags)
         fqdncacheRelease(f);
         f = NULL;
     } else if (f->flags.negcached) {
+        debugs(35, 5, "negative HIT: " << addr);
         ++ FqdncacheStats.negative_hits;
         // ignore f->error_message: the caller just checks FQDN cache presence
         return NULL;
     } else {
+        debugs(35, 5, "HIT: " << addr);
         ++ FqdncacheStats.hits;
         f->lastref = squid_curtime;
         // ignore f->error_message: the caller just checks FQDN cache presence
@@ -508,7 +513,7 @@ fqdncache_gethostbyaddr(const Ip::Address &addr, int flags)
     }
 
     /* no entry [any more] */
-
+    debugs(35, 5, "MISS: " << addr);
     ++ FqdncacheStats.misses;
 
     if (flags & FQDN_LOOKUP_IF_MISS) {

diff --git a/src/fqdncache.h b/src/fqdncache.h
index c4cc821a1225f78348f631561a1ee18ba982393c..941c065e37e4aeac2a1f65437ea513a78ea9b12a 100644 (file)
--- a/src/fqdncache.h
+++ b/src/fqdncache.h
@@ -18,6 +18,9 @@ class StoreEntry;
 namespace Dns
 {
 class LookupDetails;
+
+/// whether to do reverse DNS lookups for source IPs of accepted connections
+extern bool ResolveClientAddressesAsap;
 }
 
 typedef void FQDNH(const char *, const Dns::LookupDetails &details, void *);

diff --git a/src/log/FormatSquidIcap.cc b/src/log/FormatSquidIcap.cc
index 27f8665466c28c33e31605968d0355c688bad3fa..0ebb5eee4a111ce3b0b64ec5330ca5de8492c878 100644 (file)
--- a/src/log/FormatSquidIcap.cc
+++ b/src/log/FormatSquidIcap.cc
@@ -14,7 +14,6 @@
 
 #include "AccessLogEntry.h"
 #include "format/Quoting.h"
-#include "fqdncache.h"
 #include "HttpRequest.h"
 #include "log/File.h"
 #include "log/Formats.h"
@@ -24,18 +23,10 @@
 void
 Log::Format::SquidIcap(const AccessLogEntry::Pointer &al, Logfile * logfile)
 {
-    const char *client = NULL;
     const char *user = NULL;
     char tmp[MAX_IPSTRLEN], clientbuf[MAX_IPSTRLEN];
 
-    if (al->cache.caddr.isAnyAddr()) { // ICAP OPTIONS xactions lack client
-        client = "-";
-    } else {
-        if (Config.onoff.log_fqdn)
-            client = fqdncache_gethostbyaddr(al->cache.caddr, FQDN_LOOKUP_IF_MISS);
-        if (!client)
-            client = al->cache.caddr.toStr(clientbuf, MAX_IPSTRLEN);
-    }
+    const auto client = al->getLogClientFqdn(clientbuf, sizeof(clientbuf));
 
 #if USE_AUTH
     if (al->request != NULL && al->request->auth_user_request != NULL)

diff --git a/src/tests/stub_fqdncache.cc b/src/tests/stub_fqdncache.cc
new file mode 100644 (file)
index 0000000..e77014c
--- /dev/null
+++ b/src/tests/stub_fqdncache.cc
@@ -0,0 +1,24 @@
+/*
+ * Copyright (C) 1996-2021 The Squid Software Foundation and contributors
+ *
+ * Squid software is distributed under GPLv2+ license and includes
+ * contributions from numerous individuals and organizations.
+ * Please see the COPYING and CONTRIBUTORS files for details.
+ */
+
+#include "squid.h"
+#include "fqdncache.h"
+
+#define STUB_API "fqdncache.cc"
+#include "tests/STUB.h"
+
+bool Dns::ResolveClientAddressesAsap = false;
+
+void fqdncache_init(void) STUB
+void fqdnStats(StoreEntry *) STUB
+void fqdncacheFreeMemory(void) STUB
+void fqdncache_restart(void) STUB
+void fqdncache_purgelru(void *) STUB
+void fqdncacheAddEntryFromHosts(char *, SBufList &) STUB
+const char *fqdncache_gethostbyaddr(const Ip::Address &, int) STUB_RETVAL(nullptr)
+void fqdncache_nbgethostbyaddr(const Ip::Address &, FQDNH *, void *) STUB