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