Sdch view for net-internals

net/filter/sdch_filter.cc

 // Copyright 2014 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "net/filter/sdch_filter.h"
 
 #include <ctype.h>
 #include <limits.h>
 
 #include <algorithm>
 
 #include "base/logging.h"
 #include "base/metrics/histogram.h"
 #include "net/base/sdch_manager.h"
+#include "net/base/sdch_net_log_params.h"
 #include "net/url_request/url_request_context.h"
 
 #include "sdch/open-vcdiff/src/google/vcdecoder.h"
 
 namespace net {
 
 namespace {
 
 // Disambiguate various types of responses that trigger a meta-refresh,
 // failure, or fallback to pass-through.
@@ skipping 52 matching lines @@
 
   static int filter_use_count = 0;
   ++filter_use_count;
   if (META_REFRESH_RECOVERY == decoding_status_) {
     UMA_HISTOGRAM_COUNTS("Sdch3.FilterUseBeforeDisabling", filter_use_count);
   }
 
   if (vcdiff_streaming_decoder_.get()) {
     if (!vcdiff_streaming_decoder_->FinishDecoding()) {
       decoding_status_ = DECODING_ERROR;
-      SdchManager::SdchErrorRecovery(SdchManager::INCOMPLETE_SDCH_CONTENT);
+      LogSdchProblem(SDCH_INCOMPLETE_SDCH_CONTENT);
       // Make it possible for the user to hit reload, and get non-sdch content.
       // Note this will "wear off" quickly enough, and is just meant to assure
       // in some rare case that the user is not stuck.
       url_request_context_->sdch_manager()->BlacklistDomain(
-          url_, SdchManager::INCOMPLETE_SDCH_CONTENT);
+          url_, SDCH_INCOMPLETE_SDCH_CONTENT);
       UMA_HISTOGRAM_COUNTS("Sdch3.PartialBytesIn",
            static_cast<int>(filter_context_.GetByteReadCount()));
       UMA_HISTOGRAM_COUNTS("Sdch3.PartialVcdiffIn", source_bytes_);
       UMA_HISTOGRAM_COUNTS("Sdch3.PartialVcdiffOut", output_bytes_);
     }
   }
 
   if (!dest_buffer_excess_.empty()) {
     // Filter chaining error, or premature teardown.
-    SdchManager::SdchErrorRecovery(SdchManager::UNFLUSHED_CONTENT);
+    LogSdchProblem(SDCH_UNFLUSHED_CONTENT);
     UMA_HISTOGRAM_COUNTS("Sdch3.UnflushedBytesIn",
          static_cast<int>(filter_context_.GetByteReadCount()));
     UMA_HISTOGRAM_COUNTS("Sdch3.UnflushedBufferSize",
                          dest_buffer_excess_.size());
     UMA_HISTOGRAM_COUNTS("Sdch3.UnflushedVcdiffIn", source_bytes_);
     UMA_HISTOGRAM_COUNTS("Sdch3.UnflushedVcdiffOut", output_bytes_);
   }
 
   if (filter_context_.IsCachedContent()) {
     // Not a real error, but it is useful to have this tally.
     // TODO(jar): Remove this stat after SDCH stability is validated.
-    SdchManager::SdchErrorRecovery(SdchManager::CACHE_DECODED);
+    LogSdchProblem(SDCH_CACHE_DECODED);
     return;  // We don't need timing stats, and we aready got ratios.
   }
 
   switch (decoding_status_) {
     case DECODING_IN_PROGRESS: {
       if (output_bytes_)
         UMA_HISTOGRAM_PERCENTAGE("Sdch3.Network_Decode_Ratio_a",
             static_cast<int>(
                 (filter_context_.GetByteReadCount() * 100) / output_bytes_));
       UMA_HISTOGRAM_COUNTS("Sdch3.Network_Decode_Bytes_VcdiffOut_a",
                            output_bytes_);
       filter_context_.RecordPacketStats(FilterContext::SDCH_DECODE);
 
       // Allow latency experiments to proceed.
       url_request_context_->sdch_manager()->SetAllowLatencyExperiment(
           url_, true);
       return;
     }
     case PASS_THROUGH: {
       filter_context_.RecordPacketStats(FilterContext::SDCH_PASSTHROUGH);
       return;
     }
     case DECODING_UNINITIALIZED: {
-      SdchManager::SdchErrorRecovery(SdchManager::UNINITIALIZED);
+      LogSdchProblem(SDCH_UNINITIALIZED);
       return;
     }
     case WAITING_FOR_DICTIONARY_SELECTION: {
-      SdchManager::SdchErrorRecovery(SdchManager::PRIOR_TO_DICTIONARY);
+      LogSdchProblem(SDCH_PRIOR_TO_DICTIONARY);
       return;
     }
     case DECODING_ERROR: {
-      SdchManager::SdchErrorRecovery(SdchManager::DECODE_ERROR);
+      LogSdchProblem(SDCH_DECODE_ERROR);
       return;
     }
     case META_REFRESH_RECOVERY: {
       // Already accounted for when set.
       return;
     }
   }  // end of switch.
 }
 
 bool SdchFilter::InitDecoding(Filter::FilterType filter_type) {
@@ skipping 42 matching lines @@
       // This is where we try very hard to do error recovery, and make this
       // protocol robust in the face of proxies that do many different things.
       // If we decide that things are looking very bad (too hard to recover),
       // we may even issue a "meta-refresh" to reload the page without an SDCH
       // advertisement (so that we are sure we're not hurting anything).
       //
       // Watch out for an error page inserted by the proxy as part of a 40x
       // error response.  When we see such content molestation, we certainly
       // need to fall into the meta-refresh case.
       ResponseCorruptionDetectionCause cause = RESPONSE_NONE;
       if (filter_context_.GetResponseCode() == 404) {

[Randy Smith (Not in Mondays), 2014/10/28 22:16:27]

@baranovich: This is the beginning of the conditional cascade that Matt & I were
talking about in http://crbug.com/418975.  The information we were talking about
is what's contained in the new histograms I added below
(Sdch3.ResponseCorruptionDetection.*).  It would be useful to have that
information in the netlog (tied to a particular request) as well.  You're
welcome to skip it if you'd just like to get this CL done :-}; I added the new
histogram, and am happy to take responsibility for it and add it to
net-internals after this CL lands.

         // We could be more generous, but for now, only a "NOT FOUND" code will
         // cause a pass through.  All other bad codes will fall into a
         // meta-refresh.
-        SdchManager::SdchErrorRecovery(SdchManager::PASS_THROUGH_404_CODE);
+        LogSdchProblem(SDCH_PASS_THROUGH_404_CODE);
         cause = RESPONSE_404;
         decoding_status_ = PASS_THROUGH;
       } else if (filter_context_.GetResponseCode() != 200) {
         // We need to meta-refresh, with SDCH disabled.
         cause = RESPONSE_NOT_200;
       } else if (filter_context_.IsCachedContent()
                  && !dictionary_hash_is_plausible_) {
         // We must have hit the back button, and gotten content that was fetched
         // before we *really* advertised SDCH and a dictionary.
-        SdchManager::SdchErrorRecovery(SdchManager::PASS_THROUGH_OLD_CACHED);
+        LogSdchProblem(SDCH_PASS_THROUGH_OLD_CACHED);
         decoding_status_ = PASS_THROUGH;
         cause = RESPONSE_OLD_UNENCODED;
       } else if (possible_pass_through_) {
         // This is the potentially most graceful response. There really was no
         // error. We were just overly cautious when we added a TENTATIVE_SDCH.
         // We added the sdch coding tag, and it should not have been added.
         // This can happen in server experiments, where the server decides
         // not to use sdch, even though there is a dictionary.  To be
         // conservative, we locally added the tentative sdch (fearing that a
         // proxy stripped it!) and we must now recant (pass through).
@@ skipping 15 matching lines @@
         // We'll use a meta-refresh, and get content without asking for SDCH.
         // This will also progressively disable SDCH for this domain.
         cause = RESPONSE_CORRUPT_SDCH;
       } else {
         // One of the first 9 bytes precluded consideration as a hash.
         // This can't be an SDCH payload, even though the server said it was.
         // This is a major error, as the server or proxy tagged this SDCH even
         // though it is not!
         // Meta-refresh won't help, as we didn't advertise an SDCH dictionary!!
         // Worse yet, meta-refresh could lead to an infinite refresh loop.
-        SdchManager::SdchErrorRecovery(SdchManager::PASSING_THROUGH_NON_SDCH);
+        LogSdchProblem(SDCH_PASSING_THROUGH_NON_SDCH);
         decoding_status_ = PASS_THROUGH;
         // ... but further back-off on advertising SDCH support.
         url_request_context_->sdch_manager()->BlacklistDomain(
-            url_, SdchManager::PASSING_THROUGH_NON_SDCH);
+            url_, SDCH_PASSING_THROUGH_NON_SDCH);
         cause = RESPONSE_ENCODING_LIE;
       }
       DCHECK_NE(RESPONSE_NONE, cause);
 
       // Use if statement rather than ?: because UMA_HISTOGRAM_ENUMERATION
       // caches the histogram name based on the call site.
       if (filter_context_.IsCachedContent()) {
         UMA_HISTOGRAM_ENUMERATION(
             "Sdch3.ResponseCorruptionDetection.Cached", cause, RESPONSE_MAX);
       } else {
         UMA_HISTOGRAM_ENUMERATION(
             "Sdch3.ResponseCorruptionDetection.Uncached", cause, RESPONSE_MAX);
       }
 
       if (decoding_status_ == PASS_THROUGH) {
         dest_buffer_excess_ = dictionary_hash_;  // Send what we scanned.
       } else {
         // This is where we try to do the expensive meta-refresh.
         if (std::string::npos == mime_type_.find("text/html")) {
           // Since we can't do a meta-refresh (along with an exponential
           // backoff), we'll just make sure this NEVER happens again.
-          SdchManager::ProblemCodes problem =
-              (filter_context_.IsCachedContent() ?
-               SdchManager::CACHED_META_REFRESH_UNSUPPORTED :
-               SdchManager::META_REFRESH_UNSUPPORTED);
+          SdchProblemCode problem = (filter_context_.IsCachedContent()
+                                         ? SDCH_CACHED_META_REFRESH_UNSUPPORTED
+                                         : SDCH_META_REFRESH_UNSUPPORTED);
           url_request_context_->sdch_manager()->BlacklistDomainForever(
               url_, problem);
-          SdchManager::SdchErrorRecovery(problem);
+          LogSdchProblem(problem);
           return FILTER_ERROR;
         }
         // HTML content means we can issue a meta-refresh, and get the content
         // again, perhaps without SDCH (to be safe).
         if (filter_context_.IsCachedContent()) {
           // Cached content is probably a startup tab, so we'll just get fresh
           // content and try again, without disabling sdch.
-          SdchManager::SdchErrorRecovery(
-              SdchManager::META_REFRESH_CACHED_RECOVERY);
+          LogSdchProblem(SDCH_META_REFRESH_CACHED_RECOVERY);
         } else {
           // Since it wasn't in the cache, we definately need at least some
           // period of blacklisting to get the correct content.
           url_request_context_->sdch_manager()->BlacklistDomain(
-              url_, SdchManager::META_REFRESH_RECOVERY);
-          SdchManager::SdchErrorRecovery(SdchManager::META_REFRESH_RECOVERY);
+              url_, SDCH_META_REFRESH_RECOVERY);
+          LogSdchProblem(SDCH_META_REFRESH_RECOVERY);
         }
         decoding_status_ = META_REFRESH_RECOVERY;
         // Issue a meta redirect with SDCH disabled.
         dest_buffer_excess_ = kDecompressionErrorHtml;
       }
     } else {
       DCHECK_EQ(DECODING_IN_PROGRESS, decoding_status_);
     }
   }
 
@@ skipping 33 matching lines @@
   bool ret = vcdiff_streaming_decoder_->DecodeChunk(
     next_stream_data_, stream_data_len_, &dest_buffer_excess_);
   // Assume all data was used in decoding.
   next_stream_data_ = NULL;
   source_bytes_ += stream_data_len_;
   stream_data_len_ = 0;
   output_bytes_ += dest_buffer_excess_.size();
   if (!ret) {
     vcdiff_streaming_decoder_.reset(NULL);  // Don't call it again.
     decoding_status_ = DECODING_ERROR;
-    SdchManager::SdchErrorRecovery(SdchManager::DECODE_BODY_ERROR);
+    LogSdchProblem(SDCH_DECODE_BODY_ERROR);
     return FILTER_ERROR;
   }
 
   amount = OutputBufferExcess(dest_buffer, available_space);
   *dest_len += amount;
   dest_buffer += amount;
   available_space -= amount;
   if (0 == available_space && !dest_buffer_excess_.empty())
       return FILTER_OK;
   return FILTER_NEED_MORE_DATA;
@@ skipping 18 matching lines @@
   if (stream_data_len_ > 0)
     next_stream_data_ += bytes_needed;
   else
     next_stream_data_ = NULL;
 
   DCHECK(!dictionary_.get());
   dictionary_hash_is_plausible_ = true;  // Assume plausible, but check.
 
   if ('\0' == dictionary_hash_[kServerIdLength - 1]) {
     SdchManager* manager(url_request_context_->sdch_manager());
-    manager->GetVcdiffDictionary(
+    SdchProblemCode rv = manager->GetVcdiffDictionary(
         std::string(dictionary_hash_, 0, kServerIdLength - 1),
-        url_, &dictionary_);
+        url_,
+        &dictionary_);
+    if (rv != SDCH_OK)
+      LogSdchProblem(rv);
   } else {
     dictionary_hash_is_plausible_ = false;
   }
 
   if (!dictionary_.get()) {
     DCHECK(dictionary_hash_.size() == kServerIdLength);
     // Since dictionary was not found, check to see if hash was even plausible.
     for (size_t i = 0; i < kServerIdLength - 1; ++i) {
       char base64_char = dictionary_hash_[i];
       if (!isalnum(base64_char) && '-' != base64_char && '_' != base64_char) {
         dictionary_hash_is_plausible_ = false;
         break;
       }
     }
     if (dictionary_hash_is_plausible_)
-      SdchManager::SdchErrorRecovery(SdchManager::DICTIONARY_HASH_NOT_FOUND);
+      LogSdchProblem(SDCH_DICTIONARY_HASH_NOT_FOUND);
     else
-      SdchManager::SdchErrorRecovery(SdchManager::DICTIONARY_HASH_MALFORMED);
+      LogSdchProblem(SDCH_DICTIONARY_HASH_MALFORMED);
     decoding_status_ = DECODING_ERROR;
     return FILTER_ERROR;
   }
   vcdiff_streaming_decoder_.reset(new open_vcdiff::VCDiffStreamingDecoder);
   vcdiff_streaming_decoder_->SetAllowVcdTarget(false);
   vcdiff_streaming_decoder_->StartDecoding(dictionary_->text().data(),
                                            dictionary_->text().size());
   decoding_status_ = DECODING_IN_PROGRESS;
   return FILTER_OK;
 }
 
 int SdchFilter::OutputBufferExcess(char* const dest_buffer,
                                    size_t available_space) {
   if (dest_buffer_excess_.empty())
     return 0;
   DCHECK(dest_buffer_excess_.size() > dest_buffer_excess_index_);
   size_t amount = std::min(available_space,
       dest_buffer_excess_.size() - dest_buffer_excess_index_);
   memcpy(dest_buffer, dest_buffer_excess_.data() + dest_buffer_excess_index_,
          amount);
   dest_buffer_excess_index_ += amount;
   if (dest_buffer_excess_.size() <= dest_buffer_excess_index_) {
     DCHECK(dest_buffer_excess_.size() == dest_buffer_excess_index_);
     dest_buffer_excess_.clear();
     dest_buffer_excess_index_ = 0;
   }
   return amount;
 }
 
+void SdchFilter::LogSdchProblem(SdchProblemCode problem) {
+  SdchManager::SdchErrorRecovery(problem);
+  filter_context_.GetNetLog().AddEvent(
+      NetLog::TYPE_SDCH_DECODING_ERROR,
+      base::Bind(&NetLogSdchResourceProblemCallback, problem));
+}
+
 }  // namespace net