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