Home | History | Annotate | Download | only in engine 
      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   // TODO(zea): if the network is offline, don't attempt to connect.
    188   // See crbug.com/396687
    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     // TODO(zea): make the above statement actually true. See crbug.com/396687
    243     SignalConnectionReset(NETWORK_CHANGE);
    244     return;
    245   }
    246 
    247   DVLOG(1) << "Connection type changed to " << type << ", reconnecting.";
    248   waiting_for_network_online_ = false;
    249   SignalConnectionReset(NETWORK_CHANGE);
    250 }
    251 
    252 GURL ConnectionFactoryImpl::GetCurrentEndpoint() const {
    253   // Note that IsEndpointReachable() returns false anytime connecting_ is true,
    254   // so while connecting this always uses |next_endpoint_|.
    255   if (IsEndpointReachable())
    256     return mcs_endpoints_[last_successful_endpoint_];
    257   return mcs_endpoints_[next_endpoint_];
    258 }
    259 
    260 net::IPEndPoint ConnectionFactoryImpl::GetPeerIP() {
    261   if (!socket_handle_.socket())
    262     return net::IPEndPoint();
    263 
    264   net::IPEndPoint ip_endpoint;
    265   int result = socket_handle_.socket()->GetPeerAddress(&ip_endpoint);
    266   if (result != net::OK)
    267     return net::IPEndPoint();
    268 
    269   return ip_endpoint;
    270 }
    271 
    272 void ConnectionFactoryImpl::ConnectImpl() {
    273   DCHECK(!IsEndpointReachable());
    274   DCHECK(!socket_handle_.socket());
    275 
    276   // TODO(zea): if the network is offline, don't attempt to connect.
    277   // See crbug.com/396687
    278 
    279   connecting_ = true;
    280   GURL current_endpoint = GetCurrentEndpoint();
    281   recorder_->RecordConnectionInitiated(current_endpoint.host());
    282   int status = network_session_->proxy_service()->ResolveProxy(
    283       current_endpoint,
    284       &proxy_info_,
    285       base::Bind(&ConnectionFactoryImpl::OnProxyResolveDone,
    286                  weak_ptr_factory_.GetWeakPtr()),
    287       &pac_request_,
    288       bound_net_log_);
    289   if (status != net::ERR_IO_PENDING)
    290     OnProxyResolveDone(status);
    291 }
    292 
    293 void ConnectionFactoryImpl::InitHandler() {
    294   // May be null in tests.
    295   mcs_proto::LoginRequest login_request;
    296   if (!request_builder_.is_null()) {
    297     request_builder_.Run(&login_request);
    298     DCHECK(login_request.IsInitialized());
    299   }
    300 
    301   connection_handler_->Init(login_request, socket_handle_.socket());
    302 }
    303 
    304 scoped_ptr<net::BackoffEntry> ConnectionFactoryImpl::CreateBackoffEntry(
    305     const net::BackoffEntry::Policy* const policy) {
    306   return scoped_ptr<net::BackoffEntry>(new net::BackoffEntry(policy));
    307 }
    308 
    309 scoped_ptr<ConnectionHandler> ConnectionFactoryImpl::CreateConnectionHandler(
    310     base::TimeDelta read_timeout,
    311     const ConnectionHandler::ProtoReceivedCallback& read_callback,
    312     const ConnectionHandler::ProtoSentCallback& write_callback,
    313     const ConnectionHandler::ConnectionChangedCallback& connection_callback) {
    314   return make_scoped_ptr<ConnectionHandler>(
    315       new ConnectionHandlerImpl(read_timeout,
    316                                 read_callback,
    317                                 write_callback,
    318                                 connection_callback));
    319 }
    320 
    321 base::TimeTicks ConnectionFactoryImpl::NowTicks() {
    322   return base::TimeTicks::Now();
    323 }
    324 
    325 void ConnectionFactoryImpl::OnConnectDone(int result) {
    326   if (result != net::OK) {
    327     // If the connection fails, try another proxy.
    328     result = ReconsiderProxyAfterError(result);
    329     // ReconsiderProxyAfterError either returns an error (in which case it is
    330     // not reconsidering a proxy) or returns ERR_IO_PENDING if it is considering
    331     // another proxy.
    332     DCHECK_NE(result, net::OK);
    333     if (result == net::ERR_IO_PENDING)
    334       return;  // Proxy reconsideration pending. Return.
    335     LOG(ERROR) << "Failed to connect to MCS endpoint with error " << result;
    336     UMA_HISTOGRAM_BOOLEAN("GCM.ConnectionSuccessRate", false);
    337     recorder_->RecordConnectionFailure(result);
    338     CloseSocket();
    339     backoff_entry_->InformOfRequest(false);
    340     UMA_HISTOGRAM_SPARSE_SLOWLY("GCM.ConnectionFailureErrorCode", result);
    341 
    342     // If there are other endpoints available, use the next endpoint on the
    343     // subsequent retry.
    344     next_endpoint_++;
    345     if (next_endpoint_ >= mcs_endpoints_.size())
    346       next_endpoint_ = 0;
    347     connecting_ = false;
    348     Connect();
    349     return;
    350   }
    351 
    352   UMA_HISTOGRAM_BOOLEAN("GCM.ConnectionSuccessRate", true);
    353   UMA_HISTOGRAM_COUNTS("GCM.ConnectionEndpoint", next_endpoint_);
    354   UMA_HISTOGRAM_BOOLEAN("GCM.ConnectedViaProxy",
    355                         !(proxy_info_.is_empty() || proxy_info_.is_direct()));
    356   ReportSuccessfulProxyConnection();
    357   recorder_->RecordConnectionSuccess();
    358 
    359   // Reset the endpoint back to the default.
    360   // TODO(zea): consider prioritizing endpoints more intelligently based on
    361   // which ones succeed most for this client? Although that will affect
    362   // measuring the success rate of the default endpoint vs fallback.
    363   last_successful_endpoint_ = next_endpoint_;
    364   next_endpoint_ = 0;
    365   connecting_ = false;
    366   logging_in_ = true;
    367   DVLOG(1) << "MCS endpoint socket connection success, starting login.";
    368   InitHandler();
    369 }
    370 
    371 void ConnectionFactoryImpl::ConnectionHandlerCallback(int result) {
    372   DCHECK(!connecting_);
    373   if (result != net::OK) {
    374     // TODO(zea): Consider how to handle errors that may require some sort of
    375     // user intervention (login page, etc.).
    376     UMA_HISTOGRAM_SPARSE_SLOWLY("GCM.ConnectionDisconnectErrorCode", result);
    377     SignalConnectionReset(SOCKET_FAILURE);
    378     return;
    379   }
    380 
    381   // Handshake complete, reset backoff. If the login failed with an error,
    382   // the client should invoke SignalConnectionReset(LOGIN_FAILURE), which will
    383   // restore the previous backoff.
    384   DVLOG(1) << "Handshake complete.";
    385   last_login_time_ = NowTicks();
    386   previous_backoff_.swap(backoff_entry_);
    387   backoff_entry_->Reset();
    388   logging_in_ = false;
    389 
    390   if (listener_)
    391     listener_->OnConnected(GetCurrentEndpoint(), GetPeerIP());
    392 }
    393 
    394 // This has largely been copied from
    395 // HttpStreamFactoryImpl::Job::DoResolveProxyComplete. This should be
    396 // refactored into some common place.
    397 void ConnectionFactoryImpl::OnProxyResolveDone(int status) {
    398   pac_request_ = NULL;
    399   DVLOG(1) << "Proxy resolution status: " << status;
    400 
    401   DCHECK_NE(status, net::ERR_IO_PENDING);
    402   if (status == net::OK) {
    403     // Remove unsupported proxies from the list.
    404     proxy_info_.RemoveProxiesWithoutScheme(
    405         net::ProxyServer::SCHEME_DIRECT |
    406         net::ProxyServer::SCHEME_HTTP | net::ProxyServer::SCHEME_HTTPS |
    407         net::ProxyServer::SCHEME_SOCKS4 | net::ProxyServer::SCHEME_SOCKS5);
    408 
    409     if (proxy_info_.is_empty()) {
    410       // No proxies/direct to choose from. This happens when we don't support
    411       // any of the proxies in the returned list.
    412       status = net::ERR_NO_SUPPORTED_PROXIES;
    413     }
    414   }
    415 
    416   if (status != net::OK) {
    417     // Failed to resolve proxy. Retry later.
    418     OnConnectDone(status);
    419     return;
    420   }
    421 
    422   DVLOG(1) << "Resolved proxy with PAC:" << proxy_info_.ToPacString();
    423 
    424   net::SSLConfig ssl_config;
    425   network_session_->ssl_config_service()->GetSSLConfig(&ssl_config);
    426   status = net::InitSocketHandleForTlsConnect(
    427       net::HostPortPair::FromURL(GetCurrentEndpoint()),
    428       network_session_.get(),
    429       proxy_info_,
    430       ssl_config,
    431       ssl_config,
    432       net::PRIVACY_MODE_DISABLED,
    433       bound_net_log_,
    434       &socket_handle_,
    435       base::Bind(&ConnectionFactoryImpl::OnConnectDone,
    436                  weak_ptr_factory_.GetWeakPtr()));
    437   if (status != net::ERR_IO_PENDING)
    438     OnConnectDone(status);
    439 }
    440 
    441 // This has largely been copied from
    442 // HttpStreamFactoryImpl::Job::ReconsiderProxyAfterError. This should be
    443 // refactored into some common place.
    444 // This method reconsiders the proxy on certain errors. If it does reconsider
    445 // a proxy it always returns ERR_IO_PENDING and posts a call to
    446 // OnProxyResolveDone with the result of the reconsideration.
    447 int ConnectionFactoryImpl::ReconsiderProxyAfterError(int error) {
    448   DCHECK(!pac_request_);
    449   DCHECK_NE(error, net::OK);
    450   DCHECK_NE(error, net::ERR_IO_PENDING);
    451   // A failure to resolve the hostname or any error related to establishing a
    452   // TCP connection could be grounds for trying a new proxy configuration.
    453   //
    454   // Why do this when a hostname cannot be resolved?  Some URLs only make sense
    455   // to proxy servers.  The hostname in those URLs might fail to resolve if we
    456   // are still using a non-proxy config.  We need to check if a proxy config
    457   // now exists that corresponds to a proxy server that could load the URL.
    458   //
    459   switch (error) {
    460     case net::ERR_PROXY_CONNECTION_FAILED:
    461     case net::ERR_NAME_NOT_RESOLVED:
    462     case net::ERR_INTERNET_DISCONNECTED:
    463     case net::ERR_ADDRESS_UNREACHABLE:
    464     case net::ERR_CONNECTION_CLOSED:
    465     case net::ERR_CONNECTION_TIMED_OUT:
    466     case net::ERR_CONNECTION_RESET:
    467     case net::ERR_CONNECTION_REFUSED:
    468     case net::ERR_CONNECTION_ABORTED:
    469     case net::ERR_TIMED_OUT:
    470     case net::ERR_TUNNEL_CONNECTION_FAILED:
    471     case net::ERR_SOCKS_CONNECTION_FAILED:
    472     // This can happen in the case of trying to talk to a proxy using SSL, and
    473     // ending up talking to a captive portal that supports SSL instead.
    474     case net::ERR_PROXY_CERTIFICATE_INVALID:
    475     // This can happen when trying to talk SSL to a non-SSL server (Like a
    476     // captive portal).
    477     case net::ERR_SSL_PROTOCOL_ERROR:
    478       break;
    479     case net::ERR_SOCKS_CONNECTION_HOST_UNREACHABLE:
    480       // Remap the SOCKS-specific "host unreachable" error to a more
    481       // generic error code (this way consumers like the link doctor
    482       // know to substitute their error page).
    483       //
    484       // Note that if the host resolving was done by the SOCKS5 proxy, we can't
    485       // differentiate between a proxy-side "host not found" versus a proxy-side
    486       // "address unreachable" error, and will report both of these failures as
    487       // ERR_ADDRESS_UNREACHABLE.
    488       return net::ERR_ADDRESS_UNREACHABLE;
    489     default:
    490       return error;
    491   }
    492 
    493   net::SSLConfig ssl_config;
    494   network_session_->ssl_config_service()->GetSSLConfig(&ssl_config);
    495   if (proxy_info_.is_https() && ssl_config.send_client_cert) {
    496     network_session_->ssl_client_auth_cache()->Remove(
    497         proxy_info_.proxy_server().host_port_pair());
    498   }
    499 
    500   int status = network_session_->proxy_service()->ReconsiderProxyAfterError(
    501       GetCurrentEndpoint(), error, &proxy_info_,
    502       base::Bind(&ConnectionFactoryImpl::OnProxyResolveDone,
    503                  weak_ptr_factory_.GetWeakPtr()),
    504       &pac_request_,
    505       bound_net_log_);
    506   if (status == net::OK || status == net::ERR_IO_PENDING) {
    507     CloseSocket();
    508   } else {
    509     // If ReconsiderProxyAfterError() failed synchronously, it means
    510     // there was nothing left to fall-back to, so fail the transaction
    511     // with the last connection error we got.
    512     status = error;
    513   }
    514 
    515   // If there is new proxy info, post OnProxyResolveDone to retry it. Otherwise,
    516   // if there was an error falling back, fail synchronously.
    517   if (status == net::OK) {
    518     base::MessageLoop::current()->PostTask(
    519         FROM_HERE,
    520         base::Bind(&ConnectionFactoryImpl::OnProxyResolveDone,
    521                    weak_ptr_factory_.GetWeakPtr(), status));
    522     status = net::ERR_IO_PENDING;
    523   }
    524   return status;
    525 }
    526 
    527 void ConnectionFactoryImpl::ReportSuccessfulProxyConnection() {
    528   if (network_session_ && network_session_->proxy_service())
    529     network_session_->proxy_service()->ReportSuccess(proxy_info_);
    530 }
    531 
    532 void ConnectionFactoryImpl::CloseSocket() {
    533   // The connection handler needs to be reset, else it'll attempt to keep using
    534   // the destroyed socket.
    535   if (connection_handler_)
    536     connection_handler_->Reset();
    537 
    538   if (socket_handle_.socket() && socket_handle_.socket()->IsConnected())
    539     socket_handle_.socket()->Disconnect();
    540   socket_handle_.Reset();
    541 }
    542 
    543 }  // namespace gcm
    544