net/quic/quic_connection_logger.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 "net/quic/quic_connection_logger.h"
   6
   7 #include <algorithm>
   8 #include <string>
   9
  10 #include "base/bind.h"
  11 #include "base/callback.h"
  12 #include "base/metrics/histogram.h"
  13 #include "base/metrics/sparse_histogram.h"
  14 #include "base/strings/string_number_conversions.h"
  15 #include "base/values.h"
  16 #include "net/base/net_log.h"
  17 #include "net/base/net_util.h"
  18 #include "net/quic/crypto/crypto_handshake_message.h"
  19 #include "net/quic/crypto/crypto_protocol.h"
  20 #include "net/quic/quic_address_mismatch.h"
  21 #include "net/quic/quic_socket_address_coder.h"
  22
  23 using base::StringPiece;
  24 using std::string;
  25
  26 namespace net {
  27
  28 namespace {
  29
  30 // We have ranges-of-buckets in the cumulative histogram (covering 21 packet
  31 // sequences) of length 2, 3, 4, ... 22.
  32 // Hence the largest sample is bounded by the sum of those numbers.
  33 const int kBoundingSampleInCumulativeHistogram = ((2 + 22) * 21) / 2;
  34
  35 base::Value* NetLogQuicPacketCallback(const IPEndPoint* self_address,
  36                                       const IPEndPoint* peer_address,
  37                                       size_t packet_size,
  38                                       NetLog::LogLevel /* log_level */) {
  39   base::DictionaryValue* dict = new base::DictionaryValue();
  40   dict->SetString("self_address", self_address->ToString());
  41   dict->SetString("peer_address", peer_address->ToString());
  42   dict->SetInteger("size", packet_size);
  43   return dict;
  44 }
  45
  46 base::Value* NetLogQuicPacketSentCallback(
  47     QuicPacketSequenceNumber sequence_number,
  48     EncryptionLevel level,
  49     TransmissionType transmission_type,
  50     size_t packet_size,
  51     WriteResult result,
  52     NetLog::LogLevel /* log_level */) {
  53   base::DictionaryValue* dict = new base::DictionaryValue();
  54   dict->SetInteger("encryption_level", level);
  55   dict->SetInteger("transmission_type", transmission_type);
  56   dict->SetString("packet_sequence_number",
  57                   base::Uint64ToString(sequence_number));
  58   dict->SetInteger("size", packet_size);
  59   if (result.status != WRITE_STATUS_OK) {
  60     dict->SetInteger("net_error", result.error_code);
  61   }
  62   return dict;
  63 }
  64
  65 base::Value* NetLogQuicPacketRetransmittedCallback(
  66     QuicPacketSequenceNumber old_sequence_number,
  67     QuicPacketSequenceNumber new_sequence_number,
  68     NetLog::LogLevel /* log_level */) {
  69   base::DictionaryValue* dict = new base::DictionaryValue();
  70   dict->SetString("old_packet_sequence_number",
  71                   base::Uint64ToString(old_sequence_number));
  72   dict->SetString("new_packet_sequence_number",
  73                   base::Uint64ToString(new_sequence_number));
  74   return dict;
  75 }
  76
  77 base::Value* NetLogQuicPacketHeaderCallback(const QuicPacketHeader* header,
  78                                             NetLog::LogLevel /* log_level */) {
  79   base::DictionaryValue* dict = new base::DictionaryValue();
  80   dict->SetString("connection_id",
  81                   base::Uint64ToString(header->public_header.connection_id));
  82   dict->SetInteger("reset_flag", header->public_header.reset_flag);
  83   dict->SetInteger("version_flag", header->public_header.version_flag);
  84   dict->SetString("packet_sequence_number",
  85                   base::Uint64ToString(header->packet_sequence_number));
  86   dict->SetInteger("entropy_flag", header->entropy_flag);
  87   dict->SetInteger("fec_flag", header->fec_flag);
  88   dict->SetInteger("fec_group", header->fec_group);
  89   return dict;
  90 }
  91
  92 base::Value* NetLogQuicStreamFrameCallback(const QuicStreamFrame* frame,
  93                                            NetLog::LogLevel /* log_level */) {
  94   base::DictionaryValue* dict = new base::DictionaryValue();
  95   dict->SetInteger("stream_id", frame->stream_id);
  96   dict->SetBoolean("fin", frame->fin);
  97   dict->SetString("offset", base::Uint64ToString(frame->offset));
  98   dict->SetInteger("length", frame->data.TotalBufferSize());
  99   return dict;
 100 }
 101
 102 base::Value* NetLogQuicAckFrameCallback(const QuicAckFrame* frame,
 103                                         NetLog::LogLevel /* log_level */) {
 104   base::DictionaryValue* dict = new base::DictionaryValue();
 105   base::DictionaryValue* sent_info = new base::DictionaryValue();
 106   dict->Set("sent_info", sent_info);
 107   sent_info->SetString("least_unacked",
 108                        base::Uint64ToString(frame->sent_info.least_unacked));
 109   base::DictionaryValue* received_info = new base::DictionaryValue();
 110   dict->Set("received_info", received_info);
 111   received_info->SetString(
 112       "largest_observed",
 113       base::Uint64ToString(frame->received_info.largest_observed));
 114   received_info->SetBoolean("truncated", frame->received_info.is_truncated);
 115   base::ListValue* missing = new base::ListValue();
 116   received_info->Set("missing_packets", missing);
 117   const SequenceNumberSet& missing_packets =
 118       frame->received_info.missing_packets;
 119   for (SequenceNumberSet::const_iterator it = missing_packets.begin();
 120        it != missing_packets.end(); ++it) {
 121     missing->AppendString(base::Uint64ToString(*it));
 122   }
 123   return dict;
 124 }
 125
 126 base::Value* NetLogQuicCongestionFeedbackFrameCallback(
 127     const QuicCongestionFeedbackFrame* frame,
 128     NetLog::LogLevel /* log_level */) {
 129   base::DictionaryValue* dict = new base::DictionaryValue();
 130   switch (frame->type) {
 131     case kInterArrival: {
 132       dict->SetString("type", "InterArrival");
 133       base::ListValue* received = new base::ListValue();
 134       dict->Set("received_packets", received);
 135       for (TimeMap::const_iterator it =
 136                frame->inter_arrival.received_packet_times.begin();
 137            it != frame->inter_arrival.received_packet_times.end(); ++it) {
 138         string value = base::Uint64ToString(it->first) + "@" +
 139             base::Uint64ToString(it->second.ToDebuggingValue());
 140         received->AppendString(value);
 141       }
 142       break;
 143     }
 144     case kFixRate:
 145       dict->SetString("type", "FixRate");
 146       dict->SetInteger("bitrate_in_bytes_per_second",
 147                        frame->fix_rate.bitrate.ToBytesPerSecond());
 148       break;
 149     case kTCP:
 150       dict->SetString("type", "TCP");
 151       dict->SetInteger("receive_window", frame->tcp.receive_window);
 152       break;
 153   }
 154
 155   return dict;
 156 }
 157
 158 base::Value* NetLogQuicRstStreamFrameCallback(
 159     const QuicRstStreamFrame* frame,
 160     NetLog::LogLevel /* log_level */) {
 161   base::DictionaryValue* dict = new base::DictionaryValue();
 162   dict->SetInteger("stream_id", frame->stream_id);
 163   dict->SetInteger("quic_rst_stream_error", frame->error_code);
 164   dict->SetString("details", frame->error_details);
 165   return dict;
 166 }
 167
 168 base::Value* NetLogQuicConnectionCloseFrameCallback(
 169     const QuicConnectionCloseFrame* frame,
 170     NetLog::LogLevel /* log_level */) {
 171   base::DictionaryValue* dict = new base::DictionaryValue();
 172   dict->SetInteger("quic_error", frame->error_code);
 173   dict->SetString("details", frame->error_details);
 174   return dict;
 175 }
 176
 177 base::Value* NetLogQuicWindowUpdateFrameCallback(
 178     const QuicWindowUpdateFrame* frame,
 179     NetLog::LogLevel /* log_level */) {
 180   base::DictionaryValue* dict = new base::DictionaryValue();
 181   dict->SetInteger("stream_id", frame->stream_id);
 182   dict->SetString("byte_offset", base::Uint64ToString(frame->byte_offset));
 183   return dict;
 184 }
 185
 186 base::Value* NetLogQuicBlockedFrameCallback(
 187     const QuicBlockedFrame* frame,
 188     NetLog::LogLevel /* log_level */) {
 189   base::DictionaryValue* dict = new base::DictionaryValue();
 190   dict->SetInteger("stream_id", frame->stream_id);
 191   return dict;
 192 }
 193
 194 base::Value* NetLogQuicStopWaitingFrameCallback(
 195     const QuicStopWaitingFrame* frame,
 196     NetLog::LogLevel /* log_level */) {
 197   base::DictionaryValue* dict = new base::DictionaryValue();
 198   base::DictionaryValue* sent_info = new base::DictionaryValue();
 199   dict->Set("sent_info", sent_info);
 200   sent_info->SetString("least_unacked",
 201                        base::Uint64ToString(frame->least_unacked));
 202   return dict;
 203 }
 204
 205 base::Value* NetLogQuicVersionNegotiationPacketCallback(
 206     const QuicVersionNegotiationPacket* packet,
 207     NetLog::LogLevel /* log_level */) {
 208   base::DictionaryValue* dict = new base::DictionaryValue();
 209   base::ListValue* versions = new base::ListValue();
 210   dict->Set("versions", versions);
 211   for (QuicVersionVector::const_iterator it = packet->versions.begin();
 212        it != packet->versions.end(); ++it) {
 213     versions->AppendString(QuicVersionToString(*it));
 214   }
 215   return dict;
 216 }
 217
 218 base::Value* NetLogQuicCryptoHandshakeMessageCallback(
 219     const CryptoHandshakeMessage* message,
 220     NetLog::LogLevel /* log_level */) {
 221   base::DictionaryValue* dict = new base::DictionaryValue();
 222   dict->SetString("quic_crypto_handshake_message", message->DebugString());
 223   return dict;
 224 }
 225
 226 base::Value* NetLogQuicOnConnectionClosedCallback(
 227     QuicErrorCode error,
 228     bool from_peer,
 229     NetLog::LogLevel /* log_level */) {
 230   base::DictionaryValue* dict = new base::DictionaryValue();
 231   dict->SetInteger("quic_error", error);
 232   dict->SetBoolean("from_peer", from_peer);
 233   return dict;
 234 }
 235
 236 void UpdatePacketGapSentHistogram(size_t num_consecutive_missing_packets) {
 237   UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapSent",
 238                        num_consecutive_missing_packets);
 239 }
 240
 241 void UpdatePublicResetAddressMismatchHistogram(
 242     const IPEndPoint& server_hello_address,
 243     const IPEndPoint& public_reset_address) {
 244   int sample = GetAddressMismatch(server_hello_address, public_reset_address);
 245   // We are seemingly talking to an older server that does not support the
 246   // feature, so we can't report the results in the histogram.
 247   if (sample < 0) {
 248     return;
 249   }
 250   UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.PublicResetAddressMismatch",
 251                             sample, QUIC_ADDRESS_MISMATCH_MAX);
 252 }
 253
 254 const char* GetConnectionDescriptionString() {
 255   NetworkChangeNotifier::ConnectionType type =
 256       NetworkChangeNotifier::GetConnectionType();
 257   const char* description = NetworkChangeNotifier::ConnectionTypeToString(type);
 258   // Most platforms don't distingish Wifi vs Etherenet, and call everything
 259   // CONNECTION_UNKNOWN :-(.  We'll tease out some details when we are on WiFi,
 260   // and hopefully leave only ethernet (with no WiFi available) in the
 261   // CONNECTION_UNKNOWN category.  This *might* err if there is both ethernet,
 262   // as well as WiFi, where WiFi was not being used that much.
 263   // This function only seems usefully defined on Windows currently.
 264   if (type == NetworkChangeNotifier::CONNECTION_UNKNOWN ||
 265       type == NetworkChangeNotifier::CONNECTION_WIFI) {
 266     WifiPHYLayerProtocol wifi_type = GetWifiPHYLayerProtocol();
 267     switch (wifi_type) {
 268       case WIFI_PHY_LAYER_PROTOCOL_NONE:
 269         // No wifi support or no associated AP.
 270         break;
 271       case WIFI_PHY_LAYER_PROTOCOL_ANCIENT:
 272         // An obsolete modes introduced by the original 802.11, e.g. IR, FHSS.
 273         description = "CONNECTION_WIFI_ANCIENT";
 274         break;
 275       case WIFI_PHY_LAYER_PROTOCOL_A:
 276         // 802.11a, OFDM-based rates.
 277         description = "CONNECTION_WIFI_802.11a";
 278         break;
 279       case WIFI_PHY_LAYER_PROTOCOL_B:
 280         // 802.11b, DSSS or HR DSSS.
 281         description = "CONNECTION_WIFI_802.11b";
 282         break;
 283       case WIFI_PHY_LAYER_PROTOCOL_G:
 284         // 802.11g, same rates as 802.11a but compatible with 802.11b.
 285         description = "CONNECTION_WIFI_802.11g";
 286         break;
 287       case WIFI_PHY_LAYER_PROTOCOL_N:
 288         // 802.11n, HT rates.
 289         description = "CONNECTION_WIFI_802.11n";
 290         break;
 291       case WIFI_PHY_LAYER_PROTOCOL_UNKNOWN:
 292         // Unclassified mode or failure to identify.
 293         break;
 294     }
 295   }
 296   return description;
 297 }
 298
 299
 300 }  // namespace
 301
 302 QuicConnectionLogger::QuicConnectionLogger(const BoundNetLog& net_log)
 303     : net_log_(net_log),
 304       last_received_packet_sequence_number_(0),
 305       last_received_packet_size_(0),
 306       largest_received_packet_sequence_number_(0),
 307       largest_received_missing_packet_sequence_number_(0),
 308       num_out_of_order_received_packets_(0),
 309       num_packets_received_(0),
 310       num_truncated_acks_sent_(0),
 311       num_truncated_acks_received_(0),
 312       connection_description_(GetConnectionDescriptionString()) {
 313 }
 314
 315 QuicConnectionLogger::~QuicConnectionLogger() {
 316   UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderPacketsReceived",
 317                        num_out_of_order_received_packets_);
 318   UMA_HISTOGRAM_COUNTS("Net.QuicSession.TruncatedAcksSent",
 319                        num_truncated_acks_sent_);
 320   UMA_HISTOGRAM_COUNTS("Net.QuicSession.TruncatedAcksReceived",
 321                        num_truncated_acks_received_);
 322
 323   RecordLossHistograms();
 324 }
 325
 326 void QuicConnectionLogger::OnFrameAddedToPacket(const QuicFrame& frame) {
 327   switch (frame.type) {
 328     case PADDING_FRAME:
 329       break;
 330     case STREAM_FRAME:
 331       net_log_.AddEvent(
 332           NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_SENT,
 333           base::Bind(&NetLogQuicStreamFrameCallback, frame.stream_frame));
 334       break;
 335     case ACK_FRAME:
 336       net_log_.AddEvent(
 337           NetLog::TYPE_QUIC_SESSION_ACK_FRAME_SENT,
 338           base::Bind(&NetLogQuicAckFrameCallback, frame.ack_frame));
 339       if (frame.ack_frame->received_info.is_truncated)
 340         ++num_truncated_acks_sent_;
 341       break;
 342     case CONGESTION_FEEDBACK_FRAME:
 343       net_log_.AddEvent(
 344           NetLog::TYPE_QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_SENT,
 345           base::Bind(&NetLogQuicCongestionFeedbackFrameCallback,
 346                      frame.congestion_feedback_frame));
 347       break;
 348     case RST_STREAM_FRAME:
 349       UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeClient",
 350                                   frame.rst_stream_frame->error_code);
 351       net_log_.AddEvent(
 352           NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_SENT,
 353           base::Bind(&NetLogQuicRstStreamFrameCallback,
 354                      frame.rst_stream_frame));
 355       break;
 356     case CONNECTION_CLOSE_FRAME:
 357       net_log_.AddEvent(
 358           NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_SENT,
 359           base::Bind(&NetLogQuicConnectionCloseFrameCallback,
 360                      frame.connection_close_frame));
 361       break;
 362     case GOAWAY_FRAME:
 363       break;
 364     case WINDOW_UPDATE_FRAME:
 365       net_log_.AddEvent(
 366           NetLog::TYPE_QUIC_SESSION_WINDOW_UPDATE_FRAME_SENT,
 367           base::Bind(&NetLogQuicWindowUpdateFrameCallback,
 368                      frame.window_update_frame));
 369       break;
 370     case BLOCKED_FRAME:
 371       net_log_.AddEvent(
 372           NetLog::TYPE_QUIC_SESSION_BLOCKED_FRAME_SENT,
 373           base::Bind(&NetLogQuicBlockedFrameCallback,
 374                      frame.blocked_frame));
 375       break;
 376     case STOP_WAITING_FRAME:
 377       net_log_.AddEvent(
 378           NetLog::TYPE_QUIC_SESSION_STOP_WAITING_FRAME_SENT,
 379           base::Bind(&NetLogQuicStopWaitingFrameCallback,
 380                      frame.stop_waiting_frame));
 381       break;
 382     default:
 383       DCHECK(false) << "Illegal frame type: " << frame.type;
 384   }
 385 }
 386
 387 void QuicConnectionLogger::OnPacketSent(
 388     QuicPacketSequenceNumber sequence_number,
 389     EncryptionLevel level,
 390     TransmissionType transmission_type,
 391     const QuicEncryptedPacket& packet,
 392     WriteResult result) {
 393   net_log_.AddEvent(
 394       NetLog::TYPE_QUIC_SESSION_PACKET_SENT,
 395       base::Bind(&NetLogQuicPacketSentCallback, sequence_number, level,
 396                  transmission_type, packet.length(), result));
 397 }
 398
 399 void QuicConnectionLogger:: OnPacketRetransmitted(
 400       QuicPacketSequenceNumber old_sequence_number,
 401       QuicPacketSequenceNumber new_sequence_number) {
 402   net_log_.AddEvent(
 403       NetLog::TYPE_QUIC_SESSION_PACKET_RETRANSMITTED,
 404       base::Bind(&NetLogQuicPacketRetransmittedCallback,
 405                  old_sequence_number, new_sequence_number));
 406 }
 407
 408 void QuicConnectionLogger::OnPacketReceived(const IPEndPoint& self_address,
 409                                             const IPEndPoint& peer_address,
 410                                             const QuicEncryptedPacket& packet) {
 411   last_received_packet_size_ = packet.length();
 412   net_log_.AddEvent(
 413       NetLog::TYPE_QUIC_SESSION_PACKET_RECEIVED,
 414       base::Bind(&NetLogQuicPacketCallback, &self_address, &peer_address,
 415                  packet.length()));
 416 }
 417
 418 void QuicConnectionLogger::OnProtocolVersionMismatch(
 419     QuicVersion received_version) {
 420   // TODO(rtenneti): Add logging.
 421 }
 422
 423 void QuicConnectionLogger::OnPacketHeader(const QuicPacketHeader& header) {
 424   net_log_.AddEvent(
 425       NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_RECEIVED,
 426       base::Bind(&NetLogQuicPacketHeaderCallback, &header));
 427   ++num_packets_received_;
 428   if (largest_received_packet_sequence_number_ <
 429       header.packet_sequence_number) {
 430     QuicPacketSequenceNumber delta = header.packet_sequence_number -
 431         largest_received_packet_sequence_number_;
 432     if (delta > 1) {
 433       // There is a gap between the largest packet previously received and
 434       // the current packet.  This indicates either loss, or out-of-order
 435       // delivery.
 436       UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapReceived", delta - 1);
 437     }
 438     largest_received_packet_sequence_number_ = header.packet_sequence_number;
 439   }
 440   if (header.packet_sequence_number < received_packets_.size())
 441     received_packets_[header.packet_sequence_number] = true;
 442   if (header.packet_sequence_number < last_received_packet_sequence_number_) {
 443     ++num_out_of_order_received_packets_;
 444     UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderGapReceived",
 445                          last_received_packet_sequence_number_ -
 446                              header.packet_sequence_number);
 447   }
 448   last_received_packet_sequence_number_ = header.packet_sequence_number;
 449 }
 450
 451 void QuicConnectionLogger::OnStreamFrame(const QuicStreamFrame& frame) {
 452   net_log_.AddEvent(
 453       NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_RECEIVED,
 454       base::Bind(&NetLogQuicStreamFrameCallback, &frame));
 455 }
 456
 457 void QuicConnectionLogger::OnAckFrame(const QuicAckFrame& frame) {
 458   net_log_.AddEvent(
 459       NetLog::TYPE_QUIC_SESSION_ACK_FRAME_RECEIVED,
 460       base::Bind(&NetLogQuicAckFrameCallback, &frame));
 461
 462   const size_t kApproximateLargestSoloAckBytes = 100;
 463   if (last_received_packet_sequence_number_ < received_acks_.size() &&
 464       last_received_packet_size_ < kApproximateLargestSoloAckBytes)
 465     received_acks_[last_received_packet_sequence_number_] = true;
 466
 467   if (frame.received_info.is_truncated)
 468     ++num_truncated_acks_received_;
 469
 470   if (frame.received_info.missing_packets.empty())
 471     return;
 472
 473   SequenceNumberSet missing_packets = frame.received_info.missing_packets;
 474   SequenceNumberSet::const_iterator it = missing_packets.lower_bound(
 475       largest_received_missing_packet_sequence_number_);
 476   if (it == missing_packets.end())
 477     return;
 478
 479   if (*it == largest_received_missing_packet_sequence_number_) {
 480     ++it;
 481     if (it == missing_packets.end())
 482       return;
 483   }
 484   // Scan through the list and log consecutive ranges of missing packets.
 485   size_t num_consecutive_missing_packets = 0;
 486   QuicPacketSequenceNumber previous_missing_packet = *it - 1;
 487   while (it != missing_packets.end()) {
 488     if (previous_missing_packet == *it - 1) {
 489       ++num_consecutive_missing_packets;
 490     } else {
 491       DCHECK_NE(0u, num_consecutive_missing_packets);
 492       UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
 493       // Make sure this packet it included in the count.
 494       num_consecutive_missing_packets = 1;
 495     }
 496     previous_missing_packet = *it;
 497     ++it;
 498   }
 499   if (num_consecutive_missing_packets != 0) {
 500     UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
 501   }
 502   largest_received_missing_packet_sequence_number_ =
 503         *missing_packets.rbegin();
 504 }
 505
 506 void QuicConnectionLogger::OnCongestionFeedbackFrame(
 507     const QuicCongestionFeedbackFrame& frame) {
 508   net_log_.AddEvent(
 509       NetLog::TYPE_QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_RECEIVED,
 510       base::Bind(&NetLogQuicCongestionFeedbackFrameCallback, &frame));
 511 }
 512
 513 void QuicConnectionLogger::OnStopWaitingFrame(
 514     const QuicStopWaitingFrame& frame) {
 515   net_log_.AddEvent(
 516       NetLog::TYPE_QUIC_SESSION_STOP_WAITING_FRAME_RECEIVED,
 517       base::Bind(&NetLogQuicStopWaitingFrameCallback, &frame));
 518 }
 519
 520 void QuicConnectionLogger::OnRstStreamFrame(const QuicRstStreamFrame& frame) {
 521   UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeServer",
 522                               frame.error_code);
 523   net_log_.AddEvent(
 524       NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_RECEIVED,
 525       base::Bind(&NetLogQuicRstStreamFrameCallback, &frame));
 526 }
 527
 528 void QuicConnectionLogger::OnConnectionCloseFrame(
 529     const QuicConnectionCloseFrame& frame) {
 530   net_log_.AddEvent(
 531       NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_RECEIVED,
 532       base::Bind(&NetLogQuicConnectionCloseFrameCallback, &frame));
 533 }
 534
 535 void QuicConnectionLogger::OnPublicResetPacket(
 536     const QuicPublicResetPacket& packet) {
 537   net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PUBLIC_RESET_PACKET_RECEIVED);
 538   UpdatePublicResetAddressMismatchHistogram(client_address_,
 539                                             packet.client_address);
 540 }
 541
 542 void QuicConnectionLogger::OnVersionNegotiationPacket(
 543     const QuicVersionNegotiationPacket& packet) {
 544   net_log_.AddEvent(
 545       NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATION_PACKET_RECEIVED,
 546       base::Bind(&NetLogQuicVersionNegotiationPacketCallback, &packet));
 547 }
 548
 549 void QuicConnectionLogger::OnRevivedPacket(
 550     const QuicPacketHeader& revived_header,
 551     base::StringPiece payload) {
 552   net_log_.AddEvent(
 553       NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_REVIVED,
 554       base::Bind(&NetLogQuicPacketHeaderCallback, &revived_header));
 555 }
 556
 557 void QuicConnectionLogger::OnCryptoHandshakeMessageReceived(
 558     const CryptoHandshakeMessage& message) {
 559   net_log_.AddEvent(
 560       NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_RECEIVED,
 561       base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
 562
 563   if (message.tag() == kSHLO) {
 564     StringPiece address;
 565     QuicSocketAddressCoder decoder;
 566     if (message.GetStringPiece(kCADR, &address) &&
 567         decoder.Decode(address.data(), address.size())) {
 568       client_address_ = IPEndPoint(decoder.ip(), decoder.port());
 569     }
 570   }
 571 }
 572
 573 void QuicConnectionLogger::OnCryptoHandshakeMessageSent(
 574     const CryptoHandshakeMessage& message) {
 575   net_log_.AddEvent(
 576       NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_SENT,
 577       base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
 578 }
 579
 580 void QuicConnectionLogger::OnConnectionClosed(QuicErrorCode error,
 581                                               bool from_peer) {
 582   net_log_.AddEvent(
 583       NetLog::TYPE_QUIC_SESSION_CLOSED,
 584       base::Bind(&NetLogQuicOnConnectionClosedCallback, error, from_peer));
 585 }
 586
 587 void QuicConnectionLogger::OnSuccessfulVersionNegotiation(
 588     const QuicVersion& version) {
 589   string quic_version = QuicVersionToString(version);
 590   net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATED,
 591                     NetLog::StringCallback("version", &quic_version));
 592 }
 593
 594 base::HistogramBase* QuicConnectionLogger::GetPacketSequenceNumberHistogram(
 595     const char* statistic_name) const {
 596   string prefix("Net.QuicSession.PacketReceived_");
 597   return base::LinearHistogram::FactoryGet(
 598       prefix + statistic_name + connection_description_,
 599       1, received_packets_.size(), received_packets_.size() + 1,
 600       base::HistogramBase::kUmaTargetedHistogramFlag);
 601 }
 602
 603 base::HistogramBase* QuicConnectionLogger::Get6PacketHistogram(
 604     const char* which_6) const {
 605   // This histogram takes a binary encoding of the 6 consecutive packets
 606   // received.  As a result, there are 64 possible sample-patterns.
 607   string prefix("Net.QuicSession.6PacketsPatternsReceived_");
 608   return base::LinearHistogram::FactoryGet(
 609       prefix + which_6 + connection_description_, 1, 64, 65,
 610       base::HistogramBase::kUmaTargetedHistogramFlag);
 611 }
 612
 613 base::HistogramBase* QuicConnectionLogger::Get21CumulativeHistogram(
 614   const char* which_21) const {
 615   // This histogram contains, for each sequence of 21 packets, the results from
 616   // 21 distinct questions about that sequence.  Conceptually the histogtram is
 617   // broken into 21 distinct ranges, and one sample is added into each of those
 618   // ranges whenever we process a set of 21 packets.
 619   // There is a little rendundancy, as each "range" must have the same number
 620   // of samples, all told, but the histogram is a tad easier to read this way.
 621   // The questions are:
 622   // Was the first packet present (bucket 0==>no; bucket 1==>yes)
 623   // Of the first two packets, how many were present? (bucket 2==> none;
 624   //   bucket 3==> 1 of 2; bucket 4==> 2 of 2)
 625   // Of the  first three packets, how many were present? (bucket 5==>none;
 626   //   bucket 6==> 1 of 3; bucket 7==> 2 of 3; bucket 8==> 3 of 3).
 627   // etc.
 628   string prefix("Net.QuicSession.21CumulativePacketsReceived_");
 629   return base::LinearHistogram::FactoryGet(
 630       prefix + which_21 + connection_description_,
 631       1, kBoundingSampleInCumulativeHistogram,
 632       kBoundingSampleInCumulativeHistogram + 1,
 633       base::HistogramBase::kUmaTargetedHistogramFlag);
 634 }
 635
 636 // static
 637 void QuicConnectionLogger::AddTo21CumulativeHistogram(
 638     base::HistogramBase* histogram,
 639     int bit_mask_of_packets,
 640     int valid_bits_in_mask) {
 641   DCHECK_LE(valid_bits_in_mask, 21);
 642   DCHECK_LT(bit_mask_of_packets, 1 << 21);
 643   const int blank_bits_in_mask = 21 - valid_bits_in_mask;
 644   DCHECK_EQ(bit_mask_of_packets & ((1 << blank_bits_in_mask) - 1), 0);
 645   bit_mask_of_packets >>= blank_bits_in_mask;
 646   int bits_so_far = 0;
 647   int range_start = 0;
 648   for (int i = 1; i <= valid_bits_in_mask; ++i) {
 649     bits_so_far += bit_mask_of_packets & 1;
 650     bit_mask_of_packets >>= 1;
 651     DCHECK_LT(range_start + bits_so_far, kBoundingSampleInCumulativeHistogram);
 652     histogram->Add(range_start + bits_so_far);
 653     range_start += i + 1;
 654   }
 655 }
 656
 657 void QuicConnectionLogger::RecordAggregatePacketLossRate() const {
 658   // For short connections under 22 packets in length, we'll rely on the
 659   // Net.QuicSession.21CumulativePacketsReceived_* histogram to indicate packet
 660   // loss rates.  This way we avoid tremendously anomalous contributions to our
 661   // histogram.  (e.g., if we only got 5 packets, but lost 1, we'd otherwise
 662   // record a 20% loss in this histogram!). We may still get some strange data
 663   // (1 loss in 22 is still high :-/).
 664   if (largest_received_packet_sequence_number_ <= 21)
 665     return;
 666
 667   QuicPacketSequenceNumber divisor = largest_received_packet_sequence_number_;
 668   QuicPacketSequenceNumber numerator = divisor - num_packets_received_;
 669   if (divisor < 100000)
 670     numerator *= 1000;
 671   else
 672     divisor /= 1000;
 673   string prefix("Net.QuicSession.PacketLossRate_");
 674   base::HistogramBase* histogram = base::Histogram::FactoryGet(
 675       prefix + connection_description_, 1, 1000, 75,
 676       base::HistogramBase::kUmaTargetedHistogramFlag);
 677   histogram->Add(numerator / divisor);
 678 }
 679
 680 void QuicConnectionLogger::RecordLossHistograms() const {
 681   if (largest_received_packet_sequence_number_ == 0)
 682     return;  // Connection was never used.
 683   RecordAggregatePacketLossRate();
 684
 685   base::HistogramBase* is_not_ack_histogram =
 686       GetPacketSequenceNumberHistogram("IsNotAck_");
 687   base::HistogramBase* is_an_ack_histogram =
 688       GetPacketSequenceNumberHistogram("IsAnAck_");
 689   base::HistogramBase* packet_arrived_histogram =
 690       GetPacketSequenceNumberHistogram("Ack_");
 691   base::HistogramBase* packet_missing_histogram =
 692       GetPacketSequenceNumberHistogram("Nack_");
 693   base::HistogramBase* ongoing_cumulative_packet_histogram =
 694       Get21CumulativeHistogram("Some21s_");
 695   base::HistogramBase* first_cumulative_packet_histogram =
 696       Get21CumulativeHistogram("First21_");
 697   base::HistogramBase* six_packet_histogram = Get6PacketHistogram("Some6s_");
 698
 699   DCHECK_EQ(received_packets_.size(), received_acks_.size());
 700   const QuicPacketSequenceNumber last_index =
 701       std::min<QuicPacketSequenceNumber>(received_packets_.size() - 1,
 702           largest_received_packet_sequence_number_);
 703   const QuicPacketSequenceNumber index_of_first_21_contribution =
 704       std::min<QuicPacketSequenceNumber>(21, last_index);
 705   // Bit pattern of consecutively received packets that is maintained as we scan
 706   // through the received_packets_ vector. Less significant bits correspond to
 707   // less recent packets, and only the low order 21 bits are ever defined.
 708   // Bit is 1 iff corresponding packet was received.
 709   int packet_pattern_21 = 0;
 710   // Zero is an invalid packet sequence number.
 711   DCHECK(!received_packets_[0]);
 712   for (size_t i = 1; i <= last_index; ++i) {
 713     if (received_acks_[i])
 714       is_an_ack_histogram->Add(i);
 715     else
 716       is_not_ack_histogram->Add(i);
 717
 718     packet_pattern_21 >>= 1;
 719     if (received_packets_[i]) {
 720       packet_arrived_histogram->Add(i);
 721       packet_pattern_21 |= (1 << 20);  // Turn on the 21st bit.
 722     } else {
 723       packet_missing_histogram->Add(i);
 724     }
 725
 726     if (i == index_of_first_21_contribution) {
 727       AddTo21CumulativeHistogram(first_cumulative_packet_histogram,
 728                                  packet_pattern_21, i);
 729     }
 730     // We'll just record for non-overlapping ranges, to reduce histogramming
 731     // cost for now.  Each call does 21 separate histogram additions.
 732     if (i > 21 || i % 21 == 0) {
 733       AddTo21CumulativeHistogram(ongoing_cumulative_packet_histogram,
 734                                  packet_pattern_21, 21);
 735     }
 736
 737     if (i < 6)
 738       continue;  // Not enough packets to do any pattern recording.
 739     int recent_6_mask = packet_pattern_21 >> 15;
 740     DCHECK_LT(recent_6_mask, 64);
 741     if (i == 6) {
 742       Get6PacketHistogram("First6_")->Add(recent_6_mask);
 743       continue;
 744     }
 745     // Record some overlapping patterns, to get a better picture, since this is
 746     // not very expensive.
 747     if (i % 3 == 0)
 748       six_packet_histogram->Add(recent_6_mask);
 749   }
 750 }
 751
 752 }  // namespace net