google_apis/gcm/engine/connection_factory_impl.cc

   1 // Copyright (c) 2013 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "google_apis/gcm/engine/connection_factory_impl.h"
   6
   7 #include "base/message_loop/message_loop.h"
   8 #include "base/metrics/histogram.h"
   9 #include "base/metrics/sparse_histogram.h"
  10 #include "google_apis/gcm/engine/connection_handler_impl.h"
  11 #include "google_apis/gcm/monitoring/gcm_stats_recorder.h"
  12 #include "google_apis/gcm/protocol/mcs.pb.h"
  13 #include "net/base/net_errors.h"
  14 #include "net/http/http_network_session.h"
  15 #include "net/http/http_request_headers.h"
  16 #include "net/proxy/proxy_info.h"
  17 #include "net/socket/client_socket_handle.h"
  18 #include "net/socket/client_socket_pool_manager.h"
  19 #include "net/ssl/ssl_config_service.h"
  20
  21 namespace gcm {
  22
  23 namespace {
  24
  25 // The amount of time a Socket read should wait before timing out.
  26 const int kReadTimeoutMs = 30000;  // 30 seconds.
  27
  28 // If a connection is reset after succeeding within this window of time,
  29 // the previous backoff entry is restored (and the connection success is treated
  30 // as if it was transient).
  31 const int kConnectionResetWindowSecs = 10;  // 10 seconds.
  32
  33 // Decides whether the last login was within kConnectionResetWindowSecs of now
  34 // or not.
  35 bool ShouldRestorePreviousBackoff(const base::TimeTicks& login_time,
  36                                   const base::TimeTicks& now_ticks) {
  37   return !login_time.is_null() &&
  38       now_ticks - login_time <=
  39           base::TimeDelta::FromSeconds(kConnectionResetWindowSecs);
  40 }
  41
  42 }  // namespace
  43
  44 ConnectionFactoryImpl::ConnectionFactoryImpl(
  45     const std::vector<GURL>& mcs_endpoints,
  46     const net::BackoffEntry::Policy& backoff_policy,
  47     scoped_refptr<net::HttpNetworkSession> network_session,
  48     net::NetLog* net_log,
  49     GCMStatsRecorder* recorder)
  50   : mcs_endpoints_(mcs_endpoints),
  51     next_endpoint_(0),
  52     last_successful_endpoint_(0),
  53     backoff_policy_(backoff_policy),
  54     network_session_(network_session),
  55     bound_net_log_(
  56         net::BoundNetLog::Make(net_log, net::NetLog::SOURCE_SOCKET)),
  57     pac_request_(NULL),
  58     connecting_(false),
  59     waiting_for_backoff_(false),
  60     logging_in_(false),
  61     recorder_(recorder),
  62     weak_ptr_factory_(this) {
  63   DCHECK_GE(mcs_endpoints_.size(), 1U);
  64 }
  65
  66 ConnectionFactoryImpl::~ConnectionFactoryImpl() {
  67   net::NetworkChangeNotifier::RemoveIPAddressObserver(this);
  68   net::NetworkChangeNotifier::RemoveConnectionTypeObserver(this);
  69   if (pac_request_) {
  70     network_session_->proxy_service()->CancelPacRequest(pac_request_);
  71     pac_request_ = NULL;
  72   }
  73 }
  74
  75 void ConnectionFactoryImpl::Initialize(
  76     const BuildLoginRequestCallback& request_builder,
  77     const ConnectionHandler::ProtoReceivedCallback& read_callback,
  78     const ConnectionHandler::ProtoSentCallback& write_callback) {
  79   DCHECK(!connection_handler_);
  80
  81   previous_backoff_ = CreateBackoffEntry(&backoff_policy_);
  82   backoff_entry_ = CreateBackoffEntry(&backoff_policy_);
  83   request_builder_ = request_builder;
  84
  85   net::NetworkChangeNotifier::AddIPAddressObserver(this);
  86   net::NetworkChangeNotifier::AddConnectionTypeObserver(this);
  87   connection_handler_ = CreateConnectionHandler(
  88       base::TimeDelta::FromMilliseconds(kReadTimeoutMs),
  89       read_callback,
  90       write_callback,
  91       base::Bind(&ConnectionFactoryImpl::ConnectionHandlerCallback,
  92                  weak_ptr_factory_.GetWeakPtr())).Pass();
  93 }
  94
  95 ConnectionHandler* ConnectionFactoryImpl::GetConnectionHandler() const {
  96   return connection_handler_.get();
  97 }
  98
  99 void ConnectionFactoryImpl::Connect() {
 100   DCHECK(connection_handler_);
 101
 102   if (connecting_ || waiting_for_backoff_)
 103     return;  // Connection attempt already in progress or pending.
 104
 105   if (IsEndpointReachable())
 106     return;  // Already connected.
 107
 108   ConnectWithBackoff();
 109 }
 110
 111 void ConnectionFactoryImpl::ConnectWithBackoff() {
 112   // If a canary managed to connect while a backoff expiration was pending,
 113   // just cleanup the internal state.
 114   if (connecting_ || logging_in_ || IsEndpointReachable()) {
 115     waiting_for_backoff_ = false;
 116     return;
 117   }
 118
 119   if (backoff_entry_->ShouldRejectRequest()) {
 120     DVLOG(1) << "Delaying MCS endpoint connection for "
 121              << backoff_entry_->GetTimeUntilRelease().InMilliseconds()
 122              << " milliseconds.";
 123     waiting_for_backoff_ = true;
 124     recorder_->RecordConnectionDelayedDueToBackoff(
 125         backoff_entry_->GetTimeUntilRelease().InMilliseconds());
 126     base::MessageLoop::current()->PostDelayedTask(
 127         FROM_HERE,
 128         base::Bind(&ConnectionFactoryImpl::ConnectWithBackoff,
 129                    weak_ptr_factory_.GetWeakPtr()),
 130         backoff_entry_->GetTimeUntilRelease());
 131     return;
 132   }
 133
 134   DVLOG(1) << "Attempting connection to MCS endpoint.";
 135   waiting_for_backoff_ = false;
 136   ConnectImpl();
 137 }
 138
 139 bool ConnectionFactoryImpl::IsEndpointReachable() const {
 140   return connection_handler_ && connection_handler_->CanSendMessage();
 141 }
 142
 143 void ConnectionFactoryImpl::SignalConnectionReset(
 144     ConnectionResetReason reason) {
 145   // A failure can trigger multiple resets, so no need to do anything if a
 146   // connection is already in progress.
 147   if (connecting_) {
 148     DVLOG(1) << "Connection in progress, ignoring reset.";
 149     return;
 150   }
 151
 152   UMA_HISTOGRAM_ENUMERATION("GCM.ConnectionResetReason",
 153                             reason,
 154                             CONNECTION_RESET_COUNT);
 155   recorder_->RecordConnectionResetSignaled(reason);
 156   if (!last_login_time_.is_null()) {
 157     UMA_HISTOGRAM_CUSTOM_TIMES("GCM.ConnectionUpTime",
 158                                NowTicks() - last_login_time_,
 159                                base::TimeDelta::FromSeconds(1),
 160                                base::TimeDelta::FromHours(24),
 161                                50);
 162     // |last_login_time_| will be reset below, before attempting the new
 163     // connection.
 164   }
 165
 166   CloseSocket();
 167   DCHECK(!IsEndpointReachable());
 168
 169   // Network changes get special treatment as they can trigger a one-off canary
 170   // request that bypasses backoff (but does nothing if a connection is in
 171   // progress). Other connection reset events can be ignored as a connection
 172   // is already awaiting backoff expiration.
 173   if (waiting_for_backoff_ && reason != NETWORK_CHANGE) {
 174     DVLOG(1) << "Backoff expiration pending, ignoring reset.";
 175     return;
 176   }
 177
 178   if (logging_in_) {
 179     // Failures prior to login completion just reuse the existing backoff entry.
 180     logging_in_ = false;
 181     backoff_entry_->InformOfRequest(false);
 182   } else if (reason == LOGIN_FAILURE ||
 183              ShouldRestorePreviousBackoff(last_login_time_, NowTicks())) {
 184     // Failures due to login, or within the reset window of a login, restore
 185     // the backoff entry that was saved off at login completion time.
 186     backoff_entry_.swap(previous_backoff_);
 187     backoff_entry_->InformOfRequest(false);
 188   } else if (reason == NETWORK_CHANGE) {
 189     ConnectImpl();  // Canary attempts bypass backoff without resetting it.
 190     return;
 191   } else {
 192     // We shouldn't be in backoff in thise case.
 193     DCHECK_EQ(0, backoff_entry_->failure_count());
 194   }
 195   DCHECK(!connecting_);
 196   DCHECK(!waiting_for_backoff_);
 197
 198   // At this point the last login time has been consumed or deemed irrelevant,
 199   // reset it.
 200   last_login_time_ = base::TimeTicks();
 201
 202   Connect();
 203 }
 204
 205 base::TimeTicks ConnectionFactoryImpl::NextRetryAttempt() const {
 206   if (!backoff_entry_)
 207     return base::TimeTicks();
 208   return backoff_entry_->GetReleaseTime();
 209 }
 210
 211 void ConnectionFactoryImpl::OnConnectionTypeChanged(
 212     net::NetworkChangeNotifier::ConnectionType type) {
 213   if (type == net::NetworkChangeNotifier::CONNECTION_NONE)
 214     return;
 215
 216   DVLOG(1) << "Connection type changed to " << type << ", reconnecting.";
 217
 218   // The connection may have been silently dropped, attempt to reconnect.
 219   SignalConnectionReset(NETWORK_CHANGE);
 220 }
 221
 222 void ConnectionFactoryImpl::OnIPAddressChanged() {
 223   DVLOG(1) << "IP Address changed, reconnecting.";
 224
 225   // The connection may have been silently dropped, attempt to reconnect.
 226   SignalConnectionReset(NETWORK_CHANGE);
 227 }
 228
 229 GURL ConnectionFactoryImpl::GetCurrentEndpoint() const {
 230   // Note that IsEndpointReachable() returns false anytime connecting_ is true,
 231   // so while connecting this always uses |next_endpoint_|.
 232   if (IsEndpointReachable())
 233     return mcs_endpoints_[last_successful_endpoint_];
 234   return mcs_endpoints_[next_endpoint_];
 235 }
 236
 237 void ConnectionFactoryImpl::ConnectImpl() {
 238   DCHECK(!IsEndpointReachable());
 239   DCHECK(!socket_handle_.socket());
 240
 241   connecting_ = true;
 242   GURL current_endpoint = GetCurrentEndpoint();
 243   recorder_->RecordConnectionInitiated(current_endpoint.host());
 244   int status = network_session_->proxy_service()->ResolveProxy(
 245       current_endpoint,
 246       &proxy_info_,
 247       base::Bind(&ConnectionFactoryImpl::OnProxyResolveDone,
 248                  weak_ptr_factory_.GetWeakPtr()),
 249       &pac_request_,
 250       bound_net_log_);
 251   if (status != net::ERR_IO_PENDING)
 252     OnProxyResolveDone(status);
 253 }
 254
 255 void ConnectionFactoryImpl::InitHandler() {
 256   // May be null in tests.
 257   mcs_proto::LoginRequest login_request;
 258   if (!request_builder_.is_null()) {
 259     request_builder_.Run(&login_request);
 260     DCHECK(login_request.IsInitialized());
 261   }
 262
 263   connection_handler_->Init(login_request, socket_handle_.socket());
 264 }
 265
 266 scoped_ptr<net::BackoffEntry> ConnectionFactoryImpl::CreateBackoffEntry(
 267     const net::BackoffEntry::Policy* const policy) {
 268   return scoped_ptr<net::BackoffEntry>(new net::BackoffEntry(policy));
 269 }
 270
 271 scoped_ptr<ConnectionHandler> ConnectionFactoryImpl::CreateConnectionHandler(
 272     base::TimeDelta read_timeout,
 273     const ConnectionHandler::ProtoReceivedCallback& read_callback,
 274     const ConnectionHandler::ProtoSentCallback& write_callback,
 275     const ConnectionHandler::ConnectionChangedCallback& connection_callback) {
 276   return make_scoped_ptr<ConnectionHandler>(
 277       new ConnectionHandlerImpl(read_timeout,
 278                                 read_callback,
 279                                 write_callback,
 280                                 connection_callback));
 281 }
 282
 283 base::TimeTicks ConnectionFactoryImpl::NowTicks() {
 284   return base::TimeTicks::Now();
 285 }
 286
 287 void ConnectionFactoryImpl::OnConnectDone(int result) {
 288   if (result != net::OK) {
 289     // If the connection fails, try another proxy.
 290     result = ReconsiderProxyAfterError(result);
 291     // ReconsiderProxyAfterError either returns an error (in which case it is
 292     // not reconsidering a proxy) or returns ERR_IO_PENDING if it is considering
 293     // another proxy.
 294     DCHECK_NE(result, net::OK);
 295     if (result == net::ERR_IO_PENDING)
 296       return;  // Proxy reconsideration pending. Return.
 297     LOG(ERROR) << "Failed to connect to MCS endpoint with error " << result;
 298     UMA_HISTOGRAM_BOOLEAN("GCM.ConnectionSuccessRate", false);
 299     recorder_->RecordConnectionFailure(result);
 300     CloseSocket();
 301     backoff_entry_->InformOfRequest(false);
 302     UMA_HISTOGRAM_SPARSE_SLOWLY("GCM.ConnectionFailureErrorCode", result);
 303
 304     // If there are other endpoints available, use the next endpoint on the
 305     // subsequent retry.
 306     next_endpoint_++;
 307     if (next_endpoint_ >= mcs_endpoints_.size())
 308       next_endpoint_ = 0;
 309     connecting_ = false;
 310     Connect();
 311     return;
 312   }
 313
 314   UMA_HISTOGRAM_BOOLEAN("GCM.ConnectionSuccessRate", true);
 315   UMA_HISTOGRAM_COUNTS("GCM.ConnectionEndpoint", next_endpoint_);
 316   UMA_HISTOGRAM_BOOLEAN("GCM.ConnectedViaProxy",
 317                         !(proxy_info_.is_empty() || proxy_info_.is_direct()));
 318   ReportSuccessfulProxyConnection();
 319   recorder_->RecordConnectionSuccess();
 320
 321   // Reset the endpoint back to the default.
 322   // TODO(zea): consider prioritizing endpoints more intelligently based on
 323   // which ones succeed most for this client? Although that will affect
 324   // measuring the success rate of the default endpoint vs fallback.
 325   last_successful_endpoint_ = next_endpoint_;
 326   next_endpoint_ = 0;
 327   connecting_ = false;
 328   logging_in_ = true;
 329   DVLOG(1) << "MCS endpoint socket connection success, starting login.";
 330   InitHandler();
 331 }
 332
 333 void ConnectionFactoryImpl::ConnectionHandlerCallback(int result) {
 334   DCHECK(!connecting_);
 335   if (result != net::OK) {
 336     // TODO(zea): Consider how to handle errors that may require some sort of
 337     // user intervention (login page, etc.).
 338     UMA_HISTOGRAM_SPARSE_SLOWLY("GCM.ConnectionDisconnectErrorCode", result);
 339     SignalConnectionReset(SOCKET_FAILURE);
 340     return;
 341   }
 342
 343   // Handshake complete, reset backoff. If the login failed with an error,
 344   // the client should invoke SignalConnectionReset(LOGIN_FAILURE), which will
 345   // restore the previous backoff.
 346   DVLOG(1) << "Handshake complete.";
 347   last_login_time_ = NowTicks();
 348   previous_backoff_.swap(backoff_entry_);
 349   backoff_entry_->Reset();
 350   logging_in_ = false;
 351 }
 352
 353 // This has largely been copied from
 354 // HttpStreamFactoryImpl::Job::DoResolveProxyComplete. This should be
 355 // refactored into some common place.
 356 void ConnectionFactoryImpl::OnProxyResolveDone(int status) {
 357   pac_request_ = NULL;
 358   DVLOG(1) << "Proxy resolution status: " << status;
 359
 360   DCHECK_NE(status, net::ERR_IO_PENDING);
 361   if (status == net::OK) {
 362     // Remove unsupported proxies from the list.
 363     proxy_info_.RemoveProxiesWithoutScheme(
 364         net::ProxyServer::SCHEME_DIRECT |
 365         net::ProxyServer::SCHEME_HTTP | net::ProxyServer::SCHEME_HTTPS |
 366         net::ProxyServer::SCHEME_SOCKS4 | net::ProxyServer::SCHEME_SOCKS5);
 367
 368     if (proxy_info_.is_empty()) {
 369       // No proxies/direct to choose from. This happens when we don't support
 370       // any of the proxies in the returned list.
 371       status = net::ERR_NO_SUPPORTED_PROXIES;
 372     }
 373   }
 374
 375   if (status != net::OK) {
 376     // Failed to resolve proxy. Retry later.
 377     OnConnectDone(status);
 378     return;
 379   }
 380
 381   DVLOG(1) << "Resolved proxy with PAC:" << proxy_info_.ToPacString();
 382
 383   net::SSLConfig ssl_config;
 384   network_session_->ssl_config_service()->GetSSLConfig(&ssl_config);
 385   status = net::InitSocketHandleForTlsConnect(
 386       net::HostPortPair::FromURL(GetCurrentEndpoint()),
 387       network_session_.get(),
 388       proxy_info_,
 389       ssl_config,
 390       ssl_config,
 391       net::PRIVACY_MODE_DISABLED,
 392       bound_net_log_,
 393       &socket_handle_,
 394       base::Bind(&ConnectionFactoryImpl::OnConnectDone,
 395                  weak_ptr_factory_.GetWeakPtr()));
 396   if (status != net::ERR_IO_PENDING)
 397     OnConnectDone(status);
 398 }
 399
 400 // This has largely been copied from
 401 // HttpStreamFactoryImpl::Job::ReconsiderProxyAfterError. This should be
 402 // refactored into some common place.
 403 // This method reconsiders the proxy on certain errors. If it does reconsider
 404 // a proxy it always returns ERR_IO_PENDING and posts a call to
 405 // OnProxyResolveDone with the result of the reconsideration.
 406 int ConnectionFactoryImpl::ReconsiderProxyAfterError(int error) {
 407   DCHECK(!pac_request_);
 408   DCHECK_NE(error, net::OK);
 409   DCHECK_NE(error, net::ERR_IO_PENDING);
 410   // A failure to resolve the hostname or any error related to establishing a
 411   // TCP connection could be grounds for trying a new proxy configuration.
 412   //
 413   // Why do this when a hostname cannot be resolved?  Some URLs only make sense
 414   // to proxy servers.  The hostname in those URLs might fail to resolve if we
 415   // are still using a non-proxy config.  We need to check if a proxy config
 416   // now exists that corresponds to a proxy server that could load the URL.
 417   //
 418   switch (error) {
 419     case net::ERR_PROXY_CONNECTION_FAILED:
 420     case net::ERR_NAME_NOT_RESOLVED:
 421     case net::ERR_INTERNET_DISCONNECTED:
 422     case net::ERR_ADDRESS_UNREACHABLE:
 423     case net::ERR_CONNECTION_CLOSED:
 424     case net::ERR_CONNECTION_TIMED_OUT:
 425     case net::ERR_CONNECTION_RESET:
 426     case net::ERR_CONNECTION_REFUSED:
 427     case net::ERR_CONNECTION_ABORTED:
 428     case net::ERR_TIMED_OUT:
 429     case net::ERR_TUNNEL_CONNECTION_FAILED:
 430     case net::ERR_SOCKS_CONNECTION_FAILED:
 431     // This can happen in the case of trying to talk to a proxy using SSL, and
 432     // ending up talking to a captive portal that supports SSL instead.
 433     case net::ERR_PROXY_CERTIFICATE_INVALID:
 434     // This can happen when trying to talk SSL to a non-SSL server (Like a
 435     // captive portal).
 436     case net::ERR_SSL_PROTOCOL_ERROR:
 437       break;
 438     case net::ERR_SOCKS_CONNECTION_HOST_UNREACHABLE:
 439       // Remap the SOCKS-specific "host unreachable" error to a more
 440       // generic error code (this way consumers like the link doctor
 441       // know to substitute their error page).
 442       //
 443       // Note that if the host resolving was done by the SOCKS5 proxy, we can't
 444       // differentiate between a proxy-side "host not found" versus a proxy-side
 445       // "address unreachable" error, and will report both of these failures as
 446       // ERR_ADDRESS_UNREACHABLE.
 447       return net::ERR_ADDRESS_UNREACHABLE;
 448     default:
 449       return error;
 450   }
 451
 452   net::SSLConfig ssl_config;
 453   network_session_->ssl_config_service()->GetSSLConfig(&ssl_config);
 454   if (proxy_info_.is_https() && ssl_config.send_client_cert) {
 455     network_session_->ssl_client_auth_cache()->Remove(
 456         proxy_info_.proxy_server().host_port_pair());
 457   }
 458
 459   int status = network_session_->proxy_service()->ReconsiderProxyAfterError(
 460       GetCurrentEndpoint(), &proxy_info_,
 461       base::Bind(&ConnectionFactoryImpl::OnProxyResolveDone,
 462                  weak_ptr_factory_.GetWeakPtr()),
 463       &pac_request_,
 464       bound_net_log_);
 465   if (status == net::OK || status == net::ERR_IO_PENDING) {
 466     CloseSocket();
 467   } else {
 468     // If ReconsiderProxyAfterError() failed synchronously, it means
 469     // there was nothing left to fall-back to, so fail the transaction
 470     // with the last connection error we got.
 471     status = error;
 472   }
 473
 474   // If there is new proxy info, post OnProxyResolveDone to retry it. Otherwise,
 475   // if there was an error falling back, fail synchronously.
 476   if (status == net::OK) {
 477     base::MessageLoop::current()->PostTask(
 478         FROM_HERE,
 479         base::Bind(&ConnectionFactoryImpl::OnProxyResolveDone,
 480                    weak_ptr_factory_.GetWeakPtr(), status));
 481     status = net::ERR_IO_PENDING;
 482   }
 483   return status;
 484 }
 485
 486 void ConnectionFactoryImpl::ReportSuccessfulProxyConnection() {
 487   if (network_session_ && network_session_->proxy_service())
 488     network_session_->proxy_service()->ReportSuccess(proxy_info_);
 489 }
 490
 491 void ConnectionFactoryImpl::CloseSocket() {
 492   // The connection handler needs to be reset, else it'll attempt to keep using
 493   // the destroyed socket.
 494   if (connection_handler_)
 495     connection_handler_->Reset();
 496
 497   if (socket_handle_.socket() && socket_handle_.socket()->IsConnected())
 498     socket_handle_.socket()->Disconnect();
 499   socket_handle_.Reset();
 500 }
 501
 502 }  // namespace gcm