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