blob: 68d2762f8d1fb6db0ec063e173d7c69333d16018 [file] [log] [blame]
// Copyright 2012 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 "sync/internal_api/public/http_bridge.h"
#include "base/message_loop/message_loop.h"
#include "base/metrics/field_trial.h"
#include "base/metrics/histogram_macros.h"
#include "base/metrics/sparse_histogram.h"
#include "base/strings/string_number_conversions.h"
#include "base/strings/string_util.h"
#include "base/strings/stringprintf.h"
#include "net/base/load_flags.h"
#include "net/base/net_errors.h"
#include "net/http/http_cache.h"
#include "net/http/http_network_layer.h"
#include "net/http/http_request_headers.h"
#include "net/http/http_response_headers.h"
#include "net/url_request/static_http_user_agent_settings.h"
#include "net/url_request/url_fetcher.h"
#include "net/url_request/url_request_context.h"
#include "net/url_request/url_request_job_factory_impl.h"
#include "net/url_request/url_request_status.h"
#include "sync/internal_api/public/base/cancelation_signal.h"
#include "third_party/zlib/zlib.h"
namespace syncer {
namespace {
// It's possible for an http request to be silently stalled. We set a time
// limit for all http requests, beyond which the request is cancelled and
// treated as a transient failure.
const int kMaxHttpRequestTimeSeconds = 60 * 5; // 5 minutes.
// Helper method for logging timeouts via UMA.
void LogTimeout(bool timed_out) {
UMA_HISTOGRAM_BOOLEAN("Sync.URLFetchTimedOut", timed_out);
}
bool IsSyncHttpContentCompressionEnabled() {
const std::string group_name =
base::FieldTrialList::FindFullName("SyncHttpContentCompression");
return StartsWith(group_name, "Enabled", base::CompareCase::SENSITIVE);
}
void RecordSyncRequestContentLengthHistograms(int64 compressed_content_length,
int64 original_content_length) {
UMA_HISTOGRAM_COUNTS("Sync.RequestContentLength.Compressed",
compressed_content_length);
UMA_HISTOGRAM_COUNTS("Sync.RequestContentLength.Original",
original_content_length);
}
void RecordSyncResponseContentLengthHistograms(int64 compressed_content_length,
int64 original_content_length) {
UMA_HISTOGRAM_COUNTS("Sync.ResponseContentLength.Compressed",
compressed_content_length);
UMA_HISTOGRAM_COUNTS("Sync.ResponseContentLength.Original",
original_content_length);
}
// -----------------------------------------------------------------------------
// The rest of the code in the anon namespace is copied from
// components/compression/compression_utils.cc
// TODO(gangwu): crbug.com/515695. The following code is copied from
// components/compression/compression_utils.cc. We copied them because if we
// reference them, we will get cycle dependency warning. Once the functions
// have been moved from //component to //base, we can remove the following
// functions.
//------------------------------------------------------------------------------
// The difference in bytes between a zlib header and a gzip header.
const size_t kGzipZlibHeaderDifferenceBytes = 16;
// Pass an integer greater than the following get a gzip header instead of a
// zlib header when calling deflateInit2() and inflateInit2().
const int kWindowBitsToGetGzipHeader = 16;
// This describes the amount of memory zlib uses to compress data. It can go
// from 1 to 9, with 8 being the default. For details, see:
// http://www.zlib.net/manual.html (search for memLevel).
const int kZlibMemoryLevel = 8;
// This code is taken almost verbatim from third_party/zlib/compress.c. The only
// difference is deflateInit2() is called which sets the window bits to be > 16.
// That causes a gzip header to be emitted rather than a zlib header.
int GzipCompressHelper(Bytef* dest,
uLongf* dest_length,
const Bytef* source,
uLong source_length) {
z_stream stream;
stream.next_in = bit_cast<Bytef*>(source);
stream.avail_in = static_cast<uInt>(source_length);
stream.next_out = dest;
stream.avail_out = static_cast<uInt>(*dest_length);
if (static_cast<uLong>(stream.avail_out) != *dest_length)
return Z_BUF_ERROR;
stream.zalloc = static_cast<alloc_func>(0);
stream.zfree = static_cast<free_func>(0);
stream.opaque = static_cast<voidpf>(0);
gz_header gzip_header;
memset(&gzip_header, 0, sizeof(gzip_header));
int err = deflateInit2(&stream, Z_DEFAULT_COMPRESSION, Z_DEFLATED,
MAX_WBITS + kWindowBitsToGetGzipHeader,
kZlibMemoryLevel, Z_DEFAULT_STRATEGY);
if (err != Z_OK)
return err;
err = deflateSetHeader(&stream, &gzip_header);
if (err != Z_OK)
return err;
err = deflate(&stream, Z_FINISH);
if (err != Z_STREAM_END) {
deflateEnd(&stream);
return err == Z_OK ? Z_BUF_ERROR : err;
}
*dest_length = stream.total_out;
err = deflateEnd(&stream);
return err;
}
bool GzipCompress(const std::string& input, std::string* output) {
const uLongf input_size = static_cast<uLongf>(input.size());
std::vector<Bytef> compressed_data(kGzipZlibHeaderDifferenceBytes +
compressBound(input_size));
uLongf compressed_size = static_cast<uLongf>(compressed_data.size());
if (GzipCompressHelper(&compressed_data.front(), &compressed_size,
bit_cast<const Bytef*>(input.data()),
input_size) != Z_OK) {
return false;
}
compressed_data.resize(compressed_size);
output->assign(compressed_data.begin(), compressed_data.end());
return true;
}
} // namespace
HttpBridgeFactory::HttpBridgeFactory(
const scoped_refptr<net::URLRequestContextGetter>& request_context_getter,
const NetworkTimeUpdateCallback& network_time_update_callback,
CancelationSignal* cancelation_signal)
: request_context_getter_(request_context_getter),
network_time_update_callback_(network_time_update_callback),
cancelation_signal_(cancelation_signal) {
// Registration should never fail. This should happen on the UI thread during
// init. It would be impossible for a shutdown to have been requested at this
// point.
bool result = cancelation_signal_->TryRegisterHandler(this);
DCHECK(result);
}
HttpBridgeFactory::~HttpBridgeFactory() {
cancelation_signal_->UnregisterHandler(this);
}
void HttpBridgeFactory::Init(
const std::string& user_agent,
const BindToTrackerCallback& bind_to_tracker_callback) {
user_agent_ = user_agent;
bind_to_tracker_callback_ = bind_to_tracker_callback;
}
HttpPostProviderInterface* HttpBridgeFactory::Create() {
base::AutoLock lock(request_context_getter_lock_);
// If we've been asked to shut down (something which may happen asynchronously
// and at pretty much any time), then we won't have a request_context_getter_.
// Some external mechanism must ensure that this function is not called after
// we've been asked to shut down.
CHECK(request_context_getter_.get());
scoped_refptr<HttpBridge> http =
new HttpBridge(user_agent_, request_context_getter_,
network_time_update_callback_, bind_to_tracker_callback_);
http->AddRef();
return http.get();
}
void HttpBridgeFactory::Destroy(HttpPostProviderInterface* http) {
static_cast<HttpBridge*>(http)->Release();
}
void HttpBridgeFactory::OnSignalReceived() {
base::AutoLock lock(request_context_getter_lock_);
// Release |request_context_getter_| as soon as possible so that it
// is destroyed in the right order on its network task runner.
request_context_getter_ = NULL;
}
HttpBridge::URLFetchState::URLFetchState()
: url_poster(NULL),
aborted(false),
request_completed(false),
request_succeeded(false),
http_response_code(-1),
error_code(-1) {
}
HttpBridge::URLFetchState::~URLFetchState() {}
HttpBridge::HttpBridge(
const std::string& user_agent,
const scoped_refptr<net::URLRequestContextGetter>& context_getter,
const NetworkTimeUpdateCallback& network_time_update_callback,
const BindToTrackerCallback& bind_to_tracker_callback)
: created_on_loop_(base::MessageLoop::current()),
user_agent_(user_agent),
http_post_completed_(false, false),
request_context_getter_(context_getter),
network_task_runner_(request_context_getter_->GetNetworkTaskRunner()),
network_time_update_callback_(network_time_update_callback),
bind_to_tracker_callback_(bind_to_tracker_callback) {}
HttpBridge::~HttpBridge() {
}
void HttpBridge::SetExtraRequestHeaders(const char * headers) {
DCHECK(extra_headers_.empty())
<< "HttpBridge::SetExtraRequestHeaders called twice.";
extra_headers_.assign(headers);
}
void HttpBridge::SetURL(const char* url, int port) {
#if DCHECK_IS_ON()
DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
{
base::AutoLock lock(fetch_state_lock_);
DCHECK(!fetch_state_.request_completed);
}
DCHECK(url_for_request_.is_empty())
<< "HttpBridge::SetURL called more than once?!";
#endif
GURL temp(url);
GURL::Replacements replacements;
std::string port_str = base::IntToString(port);
replacements.SetPort(port_str.c_str(), url::Component(0, port_str.length()));
url_for_request_ = temp.ReplaceComponents(replacements);
}
void HttpBridge::SetPostPayload(const char* content_type,
int content_length,
const char* content) {
#if DCHECK_IS_ON()
DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
{
base::AutoLock lock(fetch_state_lock_);
DCHECK(!fetch_state_.request_completed);
}
DCHECK(content_type_.empty()) << "Bridge payload already set.";
DCHECK_GE(content_length, 0) << "Content length < 0";
#endif
content_type_ = content_type;
if (!content || (content_length == 0)) {
DCHECK_EQ(content_length, 0);
request_content_ = " "; // TODO(timsteele): URLFetcher requires non-empty
// content for POSTs whereas CURL does not, for now
// we hack this to support the sync backend.
} else {
request_content_.assign(content, content_length);
}
}
bool HttpBridge::MakeSynchronousPost(int* error_code, int* response_code) {
#if DCHECK_IS_ON()
DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
{
base::AutoLock lock(fetch_state_lock_);
DCHECK(!fetch_state_.request_completed);
}
DCHECK(url_for_request_.is_valid()) << "Invalid URL for request";
DCHECK(!content_type_.empty()) << "Payload not set";
#endif
if (!network_task_runner_->PostTask(
FROM_HERE,
base::Bind(&HttpBridge::CallMakeAsynchronousPost, this))) {
// This usually happens when we're in a unit test.
LOG(WARNING) << "Could not post CallMakeAsynchronousPost task";
return false;
}
// Block until network request completes or is aborted. See
// OnURLFetchComplete and Abort.
http_post_completed_.Wait();
base::AutoLock lock(fetch_state_lock_);
DCHECK(fetch_state_.request_completed || fetch_state_.aborted);
*error_code = fetch_state_.error_code;
*response_code = fetch_state_.http_response_code;
return fetch_state_.request_succeeded;
}
void HttpBridge::MakeAsynchronousPost() {
DCHECK(network_task_runner_->BelongsToCurrentThread());
base::AutoLock lock(fetch_state_lock_);
DCHECK(!fetch_state_.request_completed);
if (fetch_state_.aborted)
return;
// Start the timer on the network thread (the same thread progress is made
// on, and on which the url fetcher lives).
DCHECK(!fetch_state_.http_request_timeout_timer.get());
fetch_state_.http_request_timeout_timer.reset(new base::Timer(false, false));
fetch_state_.http_request_timeout_timer->Start(
FROM_HERE, base::TimeDelta::FromSeconds(kMaxHttpRequestTimeSeconds),
base::Bind(&HttpBridge::OnURLFetchTimedOut, this));
DCHECK(request_context_getter_.get());
fetch_state_.start_time = base::Time::Now();
fetch_state_.url_poster =
net::URLFetcher::Create(url_for_request_, net::URLFetcher::POST, this)
.release();
if (!bind_to_tracker_callback_.is_null())
bind_to_tracker_callback_.Run(fetch_state_.url_poster);
fetch_state_.url_poster->SetRequestContext(request_context_getter_.get());
fetch_state_.url_poster->SetExtraRequestHeaders(extra_headers_);
int64 compressed_content_size = 0;
if (IsSyncHttpContentCompressionEnabled()) {
std::string compressed_request_content;
GzipCompress(request_content_, &compressed_request_content);
compressed_content_size = compressed_request_content.size();
fetch_state_.url_poster->SetUploadData(content_type_,
compressed_request_content);
fetch_state_.url_poster->AddExtraRequestHeader("Content-Encoding: gzip");
} else {
fetch_state_.url_poster->SetUploadData(content_type_, request_content_);
fetch_state_.url_poster->AddExtraRequestHeader(base::StringPrintf(
"%s: %s", net::HttpRequestHeaders::kAcceptEncoding, "deflate"));
}
RecordSyncRequestContentLengthHistograms(compressed_content_size,
request_content_.size());
fetch_state_.url_poster->AddExtraRequestHeader(base::StringPrintf(
"%s: %s", net::HttpRequestHeaders::kUserAgent, user_agent_.c_str()));
fetch_state_.url_poster->SetLoadFlags(net::LOAD_BYPASS_CACHE |
net::LOAD_DISABLE_CACHE |
net::LOAD_DO_NOT_SAVE_COOKIES |
net::LOAD_DO_NOT_SEND_COOKIES);
fetch_state_.url_poster->Start();
}
int HttpBridge::GetResponseContentLength() const {
DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
base::AutoLock lock(fetch_state_lock_);
DCHECK(fetch_state_.request_completed);
return fetch_state_.response_content.size();
}
const char* HttpBridge::GetResponseContent() const {
DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
base::AutoLock lock(fetch_state_lock_);
DCHECK(fetch_state_.request_completed);
return fetch_state_.response_content.data();
}
const std::string HttpBridge::GetResponseHeaderValue(
const std::string& name) const {
DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
base::AutoLock lock(fetch_state_lock_);
DCHECK(fetch_state_.request_completed);
std::string value;
fetch_state_.response_headers->EnumerateHeader(NULL, name, &value);
return value;
}
void HttpBridge::Abort() {
base::AutoLock lock(fetch_state_lock_);
// Release |request_context_getter_| as soon as possible so that it is
// destroyed in the right order on its network task runner.
request_context_getter_ = NULL;
DCHECK(!fetch_state_.aborted);
if (fetch_state_.aborted || fetch_state_.request_completed)
return;
fetch_state_.aborted = true;
if (!network_task_runner_->PostTask(
FROM_HERE,
base::Bind(&HttpBridge::DestroyURLFetcherOnIOThread, this,
fetch_state_.url_poster,
fetch_state_.http_request_timeout_timer.release()))) {
// Madness ensues.
NOTREACHED() << "Could not post task to delete URLFetcher";
}
fetch_state_.url_poster = NULL;
fetch_state_.error_code = net::ERR_ABORTED;
http_post_completed_.Signal();
}
void HttpBridge::DestroyURLFetcherOnIOThread(
net::URLFetcher* fetcher,
base::Timer* fetch_timer) {
DCHECK(network_task_runner_->BelongsToCurrentThread());
if (fetch_timer)
delete fetch_timer;
delete fetcher;
}
void HttpBridge::OnURLFetchComplete(const net::URLFetcher* source) {
DCHECK(network_task_runner_->BelongsToCurrentThread());
base::AutoLock lock(fetch_state_lock_);
// Stop the request timer now that the request completed.
if (fetch_state_.http_request_timeout_timer.get())
fetch_state_.http_request_timeout_timer.reset();
if (fetch_state_.aborted)
return;
fetch_state_.end_time = base::Time::Now();
fetch_state_.request_completed = true;
fetch_state_.request_succeeded =
(net::URLRequestStatus::SUCCESS == source->GetStatus().status());
fetch_state_.http_response_code = source->GetResponseCode();
fetch_state_.error_code = source->GetStatus().error();
if (fetch_state_.request_succeeded)
LogTimeout(false);
UMA_HISTOGRAM_SPARSE_SLOWLY("Sync.URLFetchResponse",
source->GetStatus().is_success()
? source->GetResponseCode()
: source->GetStatus().ToNetError());
UMA_HISTOGRAM_LONG_TIMES("Sync.URLFetchTime",
fetch_state_.end_time - fetch_state_.start_time);
// Use a real (non-debug) log to facilitate troubleshooting in the wild.
VLOG(2) << "HttpBridge::OnURLFetchComplete for: "
<< fetch_state_.url_poster->GetURL().spec();
VLOG(1) << "HttpBridge received response code: "
<< fetch_state_.http_response_code;
source->GetResponseAsString(&fetch_state_.response_content);
fetch_state_.response_headers = source->GetResponseHeaders();
UpdateNetworkTime();
int64 compressed_content_length = fetch_state_.response_content.size();
int64 original_content_length = compressed_content_length;
if (fetch_state_.response_headers &&
fetch_state_.response_headers->HasHeaderValue("content-encoding",
"gzip")) {
compressed_content_length =
fetch_state_.response_headers->GetContentLength();
}
RecordSyncResponseContentLengthHistograms(compressed_content_length,
original_content_length);
// End of the line for url_poster_. It lives only on the IO loop.
// We defer deletion because we're inside a callback from a component of the
// URLFetcher, so it seems most natural / "polite" to let the stack unwind.
base::MessageLoop::current()->DeleteSoon(FROM_HERE, fetch_state_.url_poster);
fetch_state_.url_poster = NULL;
// Wake the blocked syncer thread in MakeSynchronousPost.
// WARNING: DONT DO ANYTHING AFTER THIS CALL! |this| may be deleted!
http_post_completed_.Signal();
}
void HttpBridge::OnURLFetchDownloadProgress(const net::URLFetcher* source,
int64 current, int64 total) {
DCHECK(network_task_runner_->BelongsToCurrentThread());
// Reset the delay when forward progress is made.
base::AutoLock lock(fetch_state_lock_);
if (fetch_state_.http_request_timeout_timer.get())
fetch_state_.http_request_timeout_timer->Reset();
}
void HttpBridge::OnURLFetchUploadProgress(const net::URLFetcher* source,
int64 current, int64 total) {
DCHECK(network_task_runner_->BelongsToCurrentThread());
// Reset the delay when forward progress is made.
base::AutoLock lock(fetch_state_lock_);
if (fetch_state_.http_request_timeout_timer.get())
fetch_state_.http_request_timeout_timer->Reset();
}
void HttpBridge::OnURLFetchTimedOut() {
DCHECK(network_task_runner_->BelongsToCurrentThread());
base::AutoLock lock(fetch_state_lock_);
if (!fetch_state_.url_poster)
return;
LogTimeout(true);
DVLOG(1) << "Sync url fetch timed out. Canceling.";
fetch_state_.end_time = base::Time::Now();
fetch_state_.request_completed = true;
fetch_state_.request_succeeded = false;
fetch_state_.http_response_code = -1;
fetch_state_.error_code = net::URLRequestStatus::FAILED;
// This method is called by the timer, not the url fetcher implementation,
// so it's safe to delete the fetcher here.
delete fetch_state_.url_poster;
fetch_state_.url_poster = NULL;
// Timer is smart enough to handle being deleted as part of the invoked task.
fetch_state_.http_request_timeout_timer.reset();
// Wake the blocked syncer thread in MakeSynchronousPost.
// WARNING: DONT DO ANYTHING AFTER THIS CALL! |this| may be deleted!
http_post_completed_.Signal();
}
net::URLRequestContextGetter* HttpBridge::GetRequestContextGetterForTest()
const {
base::AutoLock lock(fetch_state_lock_);
return request_context_getter_.get();
}
void HttpBridge::UpdateNetworkTime() {
std::string sane_time_str;
if (!fetch_state_.request_succeeded || fetch_state_.start_time.is_null() ||
fetch_state_.end_time < fetch_state_.start_time ||
!fetch_state_.response_headers ||
!fetch_state_.response_headers->EnumerateHeader(NULL, "Sane-Time-Millis",
&sane_time_str)) {
return;
}
int64 sane_time_ms = 0;
if (base::StringToInt64(sane_time_str, &sane_time_ms)) {
network_time_update_callback_.Run(
base::Time::FromJsTime(sane_time_ms),
base::TimeDelta::FromMilliseconds(1),
fetch_state_.end_time - fetch_state_.start_time);
}
}
} // namespace syncer