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(SdchManager::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);
       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(SdchManager::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(SdchManager::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(SdchManager::UNINITIALIZED);
       return;
     }
     case WAITING_FOR_DICTIONARY_SELECTION: {
-      SdchManager::SdchErrorRecovery(SdchManager::PRIOR_TO_DICTIONARY);
+      LogSdchProblem(SdchManager::PRIOR_TO_DICTIONARY);
       return;
     }
     case DECODING_ERROR: {
-      SdchManager::SdchErrorRecovery(SdchManager::DECODE_ERROR);
+      LogSdchProblem(SdchManager::DECODE_ERROR);
       return;
     }
     case META_REFRESH_RECOVERY: {
       // Already accounted for when set.
       return;
     }
   }  // end of switch.
 }
 
 bool SdchFilter::InitDecoding(Filter::FilterType filter_type) {
@@ skipping 46 matching lines @@
       // 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) {
         // 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(SdchManager::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(SdchManager::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(SdchManager::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);
         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.
@@ skipping 11 matching lines @@
         // 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);
           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(SdchManager::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);
+          LogSdchProblem(SdchManager::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(SdchManager::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(
+    SdchManager::ProblemCodes rv = manager->GetVcdiffDictionary(
         std::string(dictionary_hash_, 0, kServerIdLength - 1),
-        url_, &dictionary_);
+        url_,
+        &dictionary_);
+    if (rv != SdchManager::PROBLEM_CODE_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(SdchManager::DICTIONARY_HASH_NOT_FOUND);
     else
-      SdchManager::SdchErrorRecovery(SdchManager::DICTIONARY_HASH_MALFORMED);
+      LogSdchProblem(SdchManager::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(SdchManager::ProblemCodes problem) {
+  SdchManager::SdchErrorRecovery(problem);
+  // If we were just guessing, we should not display SDCH-decoding problems as
+  // errors.

[Randy Smith (Not in Mondays), 2014/09/18 20:55:51]

Suggestion: Move this comment to right above the !possible_pass_through_; on my
first read through, I wasn't sure what you were referring to.

+  filter_context_.GetNetLog().AddEvent(
+      NetLog::TYPE_SDCH_RESOURCE_ERROR,
+      base::Bind(&NetLogSdchResourceProblemCallback,
+                 problem,
+                 !possible_pass_through_));

[Randy Smith (Not in Mondays), 2014/09/18 20:55:51]

My read of Filter::FixupEncodingTypes() is that we won't use use
FILTER_TYPE_SDCH_POSSIBLE unless we expected an SDCH response (because we
advertised a dictionary and the server didn't say X-SDCH-Encode: 0).  In that
case, I think it's reasonable to call out problems as errors, though it's
probably worthwhile checking with Matt on what level of thing he'd like to be
seen as an "error" in net-internals.  

[baranovich, 2014/09/30 13:16:52]

You're right. I removed this

+}
+
 }  // namespace net