Temporarily re-enable DnsCacheIsolation test, and add logging.

The test is failing when an entry is unexpectedly not in the DNS cache,
this CL adds some logging to the test and to the host cache, and
re-enables the test, to help diagnose the failures that are happening
on the bots.

Bug: 1042354
Change-Id: I6b241a279aafc7a65a20aaae510d96dd0c2576fe
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2033546
Commit-Queue: Matt Menke <mmenke@chromium.org>
Reviewed-by: Eric Orth <ericorth@chromium.org>
Cr-Commit-Position: refs/heads/master@{#737512}

chrome/browser/net/network_context_configuration_browsertest.cc

@@ -1119,14 +1119,32 @@ IN_PROC_BROWSER_TEST_P(NetworkContextConfigurationBrowserTest, DiskCache) {
   }
 }
 
+// TODO(https://crbug.com/1042354): Temporary code to enanle vlogging while
+// investigating why DnsCacheIsolation test is failing. Remove this test fixture
+// and all logging added with it once the test has been fixed.
+class NetworkContextConfigurationDiskCacheIsolationBrowserTest
+    : public NetworkContextConfigurationBrowserTest {
+ public:
+  NetworkContextConfigurationDiskCacheIsolationBrowserTest() = default;
+  ~NetworkContextConfigurationDiskCacheIsolationBrowserTest() override =
+      default;
+
+  // InProcessBrowserTest:
+  void SetUpCommandLine(base::CommandLine* command_line) override {
+    command_line->AppendSwitchASCII("vmodule",
+                                    "host_cache=4,host_resolver_manager=4");
+  }
+};
+
 // Make sure that NetworkContexts have separate DNS caches.
-IN_PROC_BROWSER_TEST_P(NetworkContextConfigurationBrowserTest,
-                       DISABLED_DnsCacheIsolation) {
+IN_PROC_BROWSER_TEST_P(NetworkContextConfigurationDiskCacheIsolationBrowserTest,
+                       DnsCacheIsolation) {
   net::NetworkIsolationKey network_isolation_key =
       net::NetworkIsolationKey::CreateTransient();
   net::HostPortPair host_port_pair(kHostname, 0);
   // Resolve |host_port_pair|, which should succeed and put it in the
   // NetworkContext's cache.
+  LOG(WARNING) << "Main lookup: " << host_port_pair.ToString();
   network::DnsLookupResult result =
       network::BlockingDnsLookup(network_context(), host_port_pair,
                                  nullptr /* params */, network_isolation_key);
@@ -1139,6 +1157,8 @@ IN_PROC_BROWSER_TEST_P(NetworkContextConfigurationBrowserTest,
   // context, and make sure no result is returned.
   ForEachOtherContext(
       base::BindLambdaForTesting([&](NetworkContextType network_context_type) {
+        LOG(WARNING) << "Cache-only lookup with another context: "
+                     << host_port_pair.ToString();
         network::mojom::ResolveHostParametersPtr params =
             network::mojom::ResolveHostParameters::New();
         // Cache only lookup.
@@ -1152,6 +1172,8 @@ IN_PROC_BROWSER_TEST_P(NetworkContextConfigurationBrowserTest,
       }));
   // Do a cache-only lookup using the original network context, which should
   // return the same result it initially did.
+  LOG(WARNING) << "Cache-only lookup with original context: "
+               << host_port_pair.ToString();
   network::mojom::ResolveHostParametersPtr params =
       network::mojom::ResolveHostParameters::New();
   // Cache only lookup.
@@ -2322,6 +2344,8 @@ IN_PROC_BROWSER_TEST_P(NetworkContextConfigurationReportingAndNelBrowserTest,
       ::testing::Values(TEST_CASES(NetworkContextType::kIncognitoProfile)))
 
 INSTANTIATE_TEST_CASES_FOR_TEST_FIXTURE(NetworkContextConfigurationBrowserTest);
+INSTANTIATE_TEST_CASES_FOR_TEST_FIXTURE(
+    NetworkContextConfigurationDiskCacheIsolationBrowserTest);
 INSTANTIATE_TEST_CASES_FOR_TEST_FIXTURE(
     NetworkContextConfigurationFixedPortBrowserTest);
 INSTANTIATE_TEST_CASES_FOR_TEST_FIXTURE(

net/dns/host_cache.cc

@@ -11,6 +11,7 @@
 #include "base/metrics/histogram_macros.h"
 #include "base/numerics/safe_conversions.h"
 #include "base/strings/string_number_conversions.h"
+#include "base/strings/stringprintf.h"
 #include "base/time/default_tick_clock.h"
 #include "base/trace_event/trace_event.h"
 #include "net/base/ip_endpoint.h"
@@ -337,6 +338,10 @@ bool HostCache::Entry::IsStale(base::TimeTicks now, int network_changes) const {
   stale.expired_by = now - expires_;
   stale.network_changes = network_changes - network_changes_;
   stale.stale_hits = stale_hits_;
+  DVLOG(4) << "  HostCache::Entry::IsStale: " << stale.is_stale()
+           << ", expired_by=" << stale.expired_by.InMilliseconds()
+           << ", network_changes=" << network_changes << "/" << network_changes_
+           << ", stale_hits=" << stale_hits_;
   return stale.is_stale();
 }
 
@@ -472,18 +477,27 @@ HostCache::~HostCache() {
 
 const std::pair<const HostCache::Key, HostCache::Entry>*
 HostCache::Lookup(const Key& key, base::TimeTicks now, bool ignore_secure) {
+  Log(FROM_HERE, key);
+
   DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
-  if (caching_is_disabled())
+  if (caching_is_disabled()) {
+    DVLOG(4) << "  Caching Disabled";
     return nullptr;
+  }
 
   auto* result = LookupInternalIgnoringFields(key, now, ignore_secure);
-  if (!result)
+  if (!result) {
+    DVLOG(4) << "  Entry not found";
     return nullptr;
+  }
 
   auto* entry = &result->second;
-  if (entry->IsStale(now, network_changes_))
+  if (entry->IsStale(now, network_changes_)) {
+    DVLOG(4) << "  Entry is stale";
     return nullptr;
+  }
 
+  DVLOG(4) << "  Entry found";
   entry->CountHit(/* hit_is_stale= */ false);
   return result;
 }
@@ -493,18 +507,30 @@ const std::pair<const HostCache::Key, HostCache::Entry>* HostCache::LookupStale(
     base::TimeTicks now,
     HostCache::EntryStaleness* stale_out,
     bool ignore_secure) {
+  Log(FROM_HERE, key);
+
   DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
-  if (caching_is_disabled())
+  if (caching_is_disabled()) {
+    DVLOG(4) << "  Caching Disabled";
     return nullptr;
+  }
 
   auto* result = LookupInternalIgnoringFields(key, now, ignore_secure);
-  if (!result)
+  if (!result) {
+    DVLOG(4) << "  Entry not found";
     return nullptr;
+  }
 
   auto* entry = &result->second;
   bool is_stale = entry->IsStale(now, network_changes_);
   entry->CountHit(/* hit_is_stale= */ is_stale);
 
+  if (is_stale) {
+    DVLOG(4) << "  Returning stale hit";
+  } else {
+    DVLOG(4) << "  Returning fresh hit";
+  }
+
   if (stale_out)
     entry->GetStaleness(now, network_changes_, stale_out);
   return result;
@@ -576,10 +602,14 @@ void HostCache::Set(const Key& key,
                     const Entry& entry,
                     base::TimeTicks now,
                     base::TimeDelta ttl) {
+  Log(FROM_HERE, key);
+
   TRACE_EVENT0(NetTracingCategory(), "HostCache::Set");
   DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
-  if (caching_is_disabled())
+  if (caching_is_disabled()) {
+    DVLOG(4) << "  Not setting, caching is disabled.";
     return;
+  }
 
   bool result_changed = false;
   auto it = entries_.find(key);
@@ -672,6 +702,8 @@ void HostCache::set_persistence_delegate(PersistenceDelegate* delegate) {
 void HostCache::clear() {
   DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
 
+  DVLOG(4) << "HostCache::clear:  host_cache=" << this << ", size=" << size();
+
   // Don't bother scheduling a write if there's nothing to clear.
   if (size() == 0)
     return;
@@ -685,6 +717,9 @@ void HostCache::ClearForHosts(
     const base::Callback<bool(const std::string&)>& host_filter) {
   DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
 
+  DVLOG(4) << "HostCache::ClearForHosts:  host_cache=" << this
+           << ", size=" << size();
+
   if (host_filter.is_null()) {
     clear();
     return;
@@ -702,6 +737,8 @@ void HostCache::ClearForHosts(
     it = next_it;
   }
 
+  DVLOG(4) << "  ClearForHosts complete: size=" << size();
+
   if (delegate_ && changed)
     delegate_->ScheduleWrite();
 }
@@ -926,6 +963,7 @@ void HostCache::EvictOneEntry(base::TimeTicks now) {
     }
   }
 
+  DVLOG(4) << "  Evicting: " << KeyToString(oldest_it->first);
   entries_.erase(oldest_it);
 }
 
@@ -959,4 +997,17 @@ const HostCache::Key* HostCache::GetMatchingKey(
   return &cache_result->first;
 }
 
+void HostCache::Log(const base::Location& location, const Key& key) {
+  DVLOG(4) << "HostCache::" << location.function_name()
+           << ": host_cache=" << this << ", key=" << KeyToString(key)
+           << ", num_entries=" << entries_.size();
+}
+
+std::string HostCache::KeyToString(const HostCache::Key& key) {
+  return base::StringPrintf("(%s,%i,%X,%i,%s)", key.hostname.c_str(),
+                            key.dns_query_type, key.host_resolver_flags,
+                            key.host_resolver_source,
+                            key.network_isolation_key.ToDebugString().c_str());
+}
+
 }  // namespace net

net/dns/host_cache.h

@@ -16,6 +16,7 @@
 #include <vector>
 
 #include "base/gtest_prod_util.h"
+#include "base/location.h"
 #include "base/logging.h"
 #include "base/macros.h"
 #include "base/numerics/clamped_math.h"
@@ -419,6 +420,12 @@ class NET_EXPORT HostCache {
   // Helper to insert an Entry into the cache.
   void AddEntry(const Key& key, Entry&& entry);
 
+  // TODO(https://crbug.com/1042354):  Remove these, all callsites, and all VLOG
+  // calls in the cc file once
+  // NetworkContextConfigurationBrowserTest.DnsCacheIsolation has been fixed.
+  void Log(const base::Location& location, const Key& key);
+  std::string KeyToString(const Key& key);
+
   // Map from hostname (presumably in lowercase canonicalized format) to
   // a resolved result entry.
   EntryMap entries_;

net/dns/host_resolver_manager.cc

@@ -2819,6 +2819,11 @@ HostResolverManager::CreateRequest(
   DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
   DCHECK(!invalidation_in_progress_);
 
+  // TODO(https://crbug.com/1042354):  Remove once
+  // NetworkContextConfigurationBrowserTest.DnsCacheIsolation has been fixed.
+  DVLOG(4) << "HostResolverManager::CreateRequest: host_cache=" << host_cache
+           << ", host=" << host.ToString();
+
   // HostCaches must add invalidators (via AddHostCacheInvalidator()) before use
   // to ensure they are invalidated on network and configuration changes.
   if (host_cache)