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