src/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 "base/bind.h"
   8 #include "base/callback.h"
   9 #include "base/metrics/histogram.h"
  10 #include "base/metrics/sparse_histogram.h"
  11 #include "base/strings/string_number_conversions.h"
  12 #include "base/values.h"
  13 #include "net/base/net_log.h"
  14 #include "net/quic/crypto/crypto_handshake.h"
  15
  16 using std::string;
  17
  18 namespace net {
  19
  20 namespace {
  21
  22 base::Value* NetLogQuicPacketCallback(const IPEndPoint* self_address,
  23                                       const IPEndPoint* peer_address,
  24                                       size_t packet_size,
  25                                       NetLog::LogLevel /* log_level */) {
  26   base::DictionaryValue* dict = new base::DictionaryValue();
  27   dict->SetString("self_address", self_address->ToString());
  28   dict->SetString("peer_address", peer_address->ToString());
  29   dict->SetInteger("size", packet_size);
  30   return dict;
  31 }
  32
  33 base::Value* NetLogQuicPacketSentCallback(
  34     QuicPacketSequenceNumber sequence_number,
  35     EncryptionLevel level,
  36     size_t packet_size,
  37     WriteResult result,
  38     NetLog::LogLevel /* log_level */) {
  39   base::DictionaryValue* dict = new base::DictionaryValue();
  40   dict->SetInteger("encryption_level", level);
  41   dict->SetString("packet_sequence_number",
  42                   base::Uint64ToString(sequence_number));
  43   dict->SetInteger("size", packet_size);
  44   if (result.status != WRITE_STATUS_OK) {
  45     dict->SetInteger("net_error", result.error_code);
  46   }
  47   return dict;
  48 }
  49
  50 base::Value* NetLogQuicPacketRetransmittedCallback(
  51     QuicPacketSequenceNumber old_sequence_number,
  52     QuicPacketSequenceNumber new_sequence_number,
  53     NetLog::LogLevel /* log_level */) {
  54  base::DictionaryValue* dict = new base::DictionaryValue();
  55  dict->SetString("old_packet_sequence_number",
  56                  base::Uint64ToString(old_sequence_number));
  57  dict->SetString("new_packet_sequence_number",
  58                  base::Uint64ToString(new_sequence_number));
  59  return dict;
  60 }
  61
  62 base::Value* NetLogQuicPacketHeaderCallback(const QuicPacketHeader* header,
  63                                             NetLog::LogLevel /* log_level */) {
  64   base::DictionaryValue* dict = new base::DictionaryValue();
  65   dict->SetString("guid",
  66                   base::Uint64ToString(header->public_header.guid));
  67   dict->SetInteger("reset_flag", header->public_header.reset_flag);
  68   dict->SetInteger("version_flag", header->public_header.version_flag);
  69   dict->SetString("packet_sequence_number",
  70                   base::Uint64ToString(header->packet_sequence_number));
  71   dict->SetInteger("entropy_flag", header->entropy_flag);
  72   dict->SetInteger("fec_flag", header->fec_flag);
  73   dict->SetInteger("fec_group", header->fec_group);
  74   return dict;
  75 }
  76
  77 base::Value* NetLogQuicStreamFrameCallback(const QuicStreamFrame* frame,
  78                                            NetLog::LogLevel /* log_level */) {
  79   base::DictionaryValue* dict = new base::DictionaryValue();
  80   dict->SetInteger("stream_id", frame->stream_id);
  81   dict->SetBoolean("fin", frame->fin);
  82   dict->SetString("offset", base::Uint64ToString(frame->offset));
  83   dict->SetInteger("length", frame->data.TotalBufferSize());
  84   return dict;
  85 }
  86
  87 base::Value* NetLogQuicAckFrameCallback(const QuicAckFrame* frame,
  88                                         NetLog::LogLevel /* log_level */) {
  89   base::DictionaryValue* dict = new base::DictionaryValue();
  90   base::DictionaryValue* sent_info = new base::DictionaryValue();
  91   dict->Set("sent_info", sent_info);
  92   sent_info->SetString("least_unacked",
  93                        base::Uint64ToString(frame->sent_info.least_unacked));
  94   base::DictionaryValue* received_info = new base::DictionaryValue();
  95   dict->Set("received_info", received_info);
  96   received_info->SetString(
  97       "largest_observed",
  98       base::Uint64ToString(frame->received_info.largest_observed));
  99   received_info->SetBoolean("truncated", frame->received_info.is_truncated);
 100   base::ListValue* missing = new base::ListValue();
 101   received_info->Set("missing_packets", missing);
 102   const SequenceNumberSet& missing_packets =
 103       frame->received_info.missing_packets;
 104   for (SequenceNumberSet::const_iterator it = missing_packets.begin();
 105        it != missing_packets.end(); ++it) {
 106     missing->AppendString(base::Uint64ToString(*it));
 107   }
 108   return dict;
 109 }
 110
 111 base::Value* NetLogQuicCongestionFeedbackFrameCallback(
 112     const QuicCongestionFeedbackFrame* frame,
 113     NetLog::LogLevel /* log_level */) {
 114   base::DictionaryValue* dict = new base::DictionaryValue();
 115   switch (frame->type) {
 116     case kInterArrival: {
 117       dict->SetString("type", "InterArrival");
 118       dict->SetInteger("accumulated_number_of_lost_packets",
 119                        frame->inter_arrival.accumulated_number_of_lost_packets);
 120       base::ListValue* received = new base::ListValue();
 121       dict->Set("received_packets", received);
 122       for (TimeMap::const_iterator it =
 123                frame->inter_arrival.received_packet_times.begin();
 124            it != frame->inter_arrival.received_packet_times.end(); ++it) {
 125         std::string value = base::Uint64ToString(it->first) + "@" +
 126             base::Uint64ToString(it->second.ToDebuggingValue());
 127         received->AppendString(value);
 128       }
 129       break;
 130     }
 131     case kFixRate:
 132       dict->SetString("type", "FixRate");
 133       dict->SetInteger("bitrate_in_bytes_per_second",
 134                        frame->fix_rate.bitrate.ToBytesPerSecond());
 135       break;
 136     case kTCP:
 137       dict->SetString("type", "TCP");
 138       dict->SetInteger("accumulated_number_of_lost_packets",
 139                        frame->tcp.accumulated_number_of_lost_packets);
 140       dict->SetInteger("receive_window", frame->tcp.receive_window);
 141       break;
 142   }
 143
 144   return dict;
 145 }
 146
 147 base::Value* NetLogQuicRstStreamFrameCallback(
 148     const QuicRstStreamFrame* frame,
 149     NetLog::LogLevel /* log_level */) {
 150   base::DictionaryValue* dict = new base::DictionaryValue();
 151   dict->SetInteger("stream_id", frame->stream_id);
 152   dict->SetInteger("quic_rst_stream_error", frame->error_code);
 153   dict->SetString("details", frame->error_details);
 154   return dict;
 155 }
 156
 157 base::Value* NetLogQuicConnectionCloseFrameCallback(
 158     const QuicConnectionCloseFrame* frame,
 159     NetLog::LogLevel /* log_level */) {
 160   base::DictionaryValue* dict = new base::DictionaryValue();
 161   dict->SetInteger("quic_error", frame->error_code);
 162   dict->SetString("details", frame->error_details);
 163   return dict;
 164 }
 165
 166 base::Value* NetLogQuicVersionNegotiationPacketCallback(
 167     const QuicVersionNegotiationPacket* packet,
 168     NetLog::LogLevel /* log_level */) {
 169   base::DictionaryValue* dict = new base::DictionaryValue();
 170   base::ListValue* versions = new base::ListValue();
 171   dict->Set("versions", versions);
 172   for (QuicVersionVector::const_iterator it = packet->versions.begin();
 173        it != packet->versions.end(); ++it) {
 174     versions->AppendString(QuicVersionToString(*it));
 175   }
 176   return dict;
 177 }
 178
 179 base::Value* NetLogQuicCryptoHandshakeMessageCallback(
 180     const CryptoHandshakeMessage* message,
 181     NetLog::LogLevel /* log_level */) {
 182   base::DictionaryValue* dict = new base::DictionaryValue();
 183   dict->SetString("quic_crypto_handshake_message", message->DebugString());
 184   return dict;
 185 }
 186
 187 base::Value* NetLogQuicOnConnectionClosedCallback(
 188     QuicErrorCode error,
 189     bool from_peer,
 190     NetLog::LogLevel /* log_level */) {
 191   base::DictionaryValue* dict = new base::DictionaryValue();
 192   dict->SetInteger("quic_error", error);
 193   dict->SetBoolean("from_peer", from_peer);
 194   return dict;
 195 }
 196
 197 void UpdatePacketGapSentHistogram(size_t num_consecutive_missing_packets) {
 198   UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapSent",
 199                        num_consecutive_missing_packets);
 200 }
 201
 202 }  // namespace
 203
 204 QuicConnectionLogger::QuicConnectionLogger(const BoundNetLog& net_log)
 205     : net_log_(net_log),
 206       last_received_packet_sequence_number_(0),
 207       largest_received_packet_sequence_number_(0),
 208       largest_received_missing_packet_sequence_number_(0),
 209       out_of_order_recieved_packet_count_(0),
 210       num_truncated_acks_sent_(0),
 211       num_truncated_acks_received_(0) {
 212 }
 213
 214 QuicConnectionLogger::~QuicConnectionLogger() {
 215   UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderPacketsReceived",
 216                        out_of_order_recieved_packet_count_);
 217   UMA_HISTOGRAM_COUNTS("Net.QuicSession.TruncatedAcksSent",
 218                        num_truncated_acks_sent_);
 219   UMA_HISTOGRAM_COUNTS("Net.QuicSession.TruncatedAcksReceived",
 220                        num_truncated_acks_received_);
 221 }
 222
 223 void QuicConnectionLogger::OnFrameAddedToPacket(const QuicFrame& frame) {
 224   switch (frame.type) {
 225     case PADDING_FRAME:
 226       break;
 227     case STREAM_FRAME:
 228       net_log_.AddEvent(
 229           NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_SENT,
 230           base::Bind(&NetLogQuicStreamFrameCallback, frame.stream_frame));
 231       break;
 232     case ACK_FRAME:
 233       net_log_.AddEvent(
 234           NetLog::TYPE_QUIC_SESSION_ACK_FRAME_SENT,
 235           base::Bind(&NetLogQuicAckFrameCallback, frame.ack_frame));
 236       if (frame.ack_frame->received_info.is_truncated)
 237         ++num_truncated_acks_sent_;
 238       break;
 239     case CONGESTION_FEEDBACK_FRAME:
 240       net_log_.AddEvent(
 241           NetLog::TYPE_QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_SENT,
 242           base::Bind(&NetLogQuicCongestionFeedbackFrameCallback,
 243                      frame.congestion_feedback_frame));
 244       break;
 245     case RST_STREAM_FRAME:
 246       UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeClient",
 247                                   frame.rst_stream_frame->error_code);
 248       net_log_.AddEvent(
 249           NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_SENT,
 250           base::Bind(&NetLogQuicRstStreamFrameCallback,
 251                      frame.rst_stream_frame));
 252       break;
 253     case CONNECTION_CLOSE_FRAME:
 254       net_log_.AddEvent(
 255           NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_SENT,
 256           base::Bind(&NetLogQuicConnectionCloseFrameCallback,
 257                      frame.connection_close_frame));
 258       break;
 259     case GOAWAY_FRAME:
 260       break;
 261     default:
 262       DCHECK(false) << "Illegal frame type: " << frame.type;
 263   }
 264 }
 265
 266 void QuicConnectionLogger::OnPacketSent(
 267     QuicPacketSequenceNumber sequence_number,
 268     EncryptionLevel level,
 269     const QuicEncryptedPacket& packet,
 270     WriteResult result) {
 271   net_log_.AddEvent(
 272       NetLog::TYPE_QUIC_SESSION_PACKET_SENT,
 273       base::Bind(&NetLogQuicPacketSentCallback, sequence_number, level,
 274                  packet.length(), result));
 275 }
 276
 277 void QuicConnectionLogger:: OnPacketRetransmitted(
 278       QuicPacketSequenceNumber old_sequence_number,
 279       QuicPacketSequenceNumber new_sequence_number) {
 280   net_log_.AddEvent(
 281       NetLog::TYPE_QUIC_SESSION_PACKET_RETRANSMITTED,
 282       base::Bind(&NetLogQuicPacketRetransmittedCallback,
 283                  old_sequence_number, new_sequence_number));
 284 }
 285
 286 void QuicConnectionLogger::OnPacketReceived(const IPEndPoint& self_address,
 287                                             const IPEndPoint& peer_address,
 288                                             const QuicEncryptedPacket& packet) {
 289   net_log_.AddEvent(
 290       NetLog::TYPE_QUIC_SESSION_PACKET_RECEIVED,
 291       base::Bind(&NetLogQuicPacketCallback, &self_address, &peer_address,
 292                  packet.length()));
 293 }
 294
 295 void QuicConnectionLogger::OnProtocolVersionMismatch(
 296     QuicVersion received_version) {
 297   // TODO(rtenneti): Add logging.
 298 }
 299
 300 void QuicConnectionLogger::OnPacketHeader(const QuicPacketHeader& header) {
 301   net_log_.AddEvent(
 302       NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_RECEIVED,
 303       base::Bind(&NetLogQuicPacketHeaderCallback, &header));
 304   if (largest_received_packet_sequence_number_ <
 305       header.packet_sequence_number) {
 306     QuicPacketSequenceNumber delta = header.packet_sequence_number -
 307         largest_received_packet_sequence_number_;
 308     if (delta > 1) {
 309       // There is a gap between the largest packet previously received and
 310       // the current packet.  This indicates either loss, or out-of-order
 311       // delivery.
 312       UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapReceived", delta - 1);
 313     }
 314     largest_received_packet_sequence_number_ = header.packet_sequence_number;
 315   }
 316   if (header.packet_sequence_number < last_received_packet_sequence_number_) {
 317     ++out_of_order_recieved_packet_count_;
 318     UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderGapReceived",
 319                          last_received_packet_sequence_number_ -
 320                              header.packet_sequence_number);
 321   }
 322   last_received_packet_sequence_number_ = header.packet_sequence_number;
 323 }
 324
 325 void QuicConnectionLogger::OnStreamFrame(const QuicStreamFrame& frame) {
 326   net_log_.AddEvent(
 327       NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_RECEIVED,
 328       base::Bind(&NetLogQuicStreamFrameCallback, &frame));
 329 }
 330
 331 void QuicConnectionLogger::OnAckFrame(const QuicAckFrame& frame) {
 332   net_log_.AddEvent(
 333       NetLog::TYPE_QUIC_SESSION_ACK_FRAME_RECEIVED,
 334       base::Bind(&NetLogQuicAckFrameCallback, &frame));
 335
 336   if (frame.received_info.is_truncated)
 337     ++num_truncated_acks_received_;
 338
 339   if (frame.received_info.missing_packets.empty())
 340     return;
 341
 342   SequenceNumberSet missing_packets = frame.received_info.missing_packets;
 343   SequenceNumberSet::const_iterator it = missing_packets.lower_bound(
 344       largest_received_missing_packet_sequence_number_);
 345   if (it == missing_packets.end())
 346     return;
 347
 348   if (*it == largest_received_missing_packet_sequence_number_) {
 349     ++it;
 350     if (it == missing_packets.end())
 351       return;
 352   }
 353   // Scan through the list and log consecutive ranges of missing packets.
 354   size_t num_consecutive_missing_packets = 0;
 355   QuicPacketSequenceNumber previous_missing_packet = *it - 1;
 356   while (it != missing_packets.end()) {
 357     if (previous_missing_packet == *it - 1) {
 358       ++num_consecutive_missing_packets;
 359     } else {
 360       DCHECK_NE(0u, num_consecutive_missing_packets);
 361       UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
 362       // Make sure this packet it included in the count.
 363       num_consecutive_missing_packets = 1;
 364     }
 365     previous_missing_packet = *it;
 366     ++it;
 367   }
 368   if (num_consecutive_missing_packets != 0) {
 369     UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
 370   }
 371   largest_received_missing_packet_sequence_number_ =
 372         *missing_packets.rbegin();
 373 }
 374
 375 void QuicConnectionLogger::OnCongestionFeedbackFrame(
 376     const QuicCongestionFeedbackFrame& frame) {
 377   net_log_.AddEvent(
 378       NetLog::TYPE_QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_RECEIVED,
 379       base::Bind(&NetLogQuicCongestionFeedbackFrameCallback, &frame));
 380 }
 381
 382 void QuicConnectionLogger::OnRstStreamFrame(const QuicRstStreamFrame& frame) {
 383   UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeServer",
 384                               frame.error_code);
 385   net_log_.AddEvent(
 386       NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_RECEIVED,
 387       base::Bind(&NetLogQuicRstStreamFrameCallback, &frame));
 388 }
 389
 390 void QuicConnectionLogger::OnConnectionCloseFrame(
 391     const QuicConnectionCloseFrame& frame) {
 392   net_log_.AddEvent(
 393       NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_RECEIVED,
 394       base::Bind(&NetLogQuicConnectionCloseFrameCallback, &frame));
 395 }
 396
 397 void QuicConnectionLogger::OnPublicResetPacket(
 398     const QuicPublicResetPacket& packet) {
 399   net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PUBLIC_RESET_PACKET_RECEIVED);
 400 }
 401
 402 void QuicConnectionLogger::OnVersionNegotiationPacket(
 403     const QuicVersionNegotiationPacket& packet) {
 404   net_log_.AddEvent(
 405       NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATION_PACKET_RECEIVED,
 406       base::Bind(&NetLogQuicVersionNegotiationPacketCallback, &packet));
 407 }
 408
 409 void QuicConnectionLogger::OnRevivedPacket(
 410     const QuicPacketHeader& revived_header,
 411     base::StringPiece payload) {
 412   net_log_.AddEvent(
 413       NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_REVIVED,
 414       base::Bind(&NetLogQuicPacketHeaderCallback, &revived_header));
 415 }
 416
 417 void QuicConnectionLogger::OnCryptoHandshakeMessageReceived(
 418     const CryptoHandshakeMessage& message) {
 419   net_log_.AddEvent(
 420       NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_RECEIVED,
 421       base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
 422 }
 423
 424 void QuicConnectionLogger::OnCryptoHandshakeMessageSent(
 425     const CryptoHandshakeMessage& message) {
 426   net_log_.AddEvent(
 427       NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_SENT,
 428       base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
 429 }
 430
 431 void QuicConnectionLogger::OnConnectionClosed(QuicErrorCode error,
 432                                               bool from_peer) {
 433   net_log_.AddEvent(
 434       NetLog::TYPE_QUIC_SESSION_CLOSED,
 435       base::Bind(&NetLogQuicOnConnectionClosedCallback, error, from_peer));
 436 }
 437
 438 void QuicConnectionLogger::OnSuccessfulVersionNegotiation(
 439     const QuicVersion& version) {
 440   string quic_version = QuicVersionToString(version);
 441   net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATED,
 442                     NetLog::StringCallback("version", &quic_version));
 443 }
 444
 445 }  // namespace net