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_message.h"
  15 #include "net/quic/crypto/crypto_protocol.h"
  16 #include "net/quic/quic_address_mismatch.h"
  17 #include "net/quic/quic_socket_address_coder.h"
  18
  19 using base::StringPiece;
  20 using std::string;
  21
  22 namespace net {
  23
  24 namespace {
  25
  26 base::Value* NetLogQuicPacketCallback(const IPEndPoint* self_address,
  27                                       const IPEndPoint* peer_address,
  28                                       size_t packet_size,
  29                                       NetLog::LogLevel /* log_level */) {
  30   base::DictionaryValue* dict = new base::DictionaryValue();
  31   dict->SetString("self_address", self_address->ToString());
  32   dict->SetString("peer_address", peer_address->ToString());
  33   dict->SetInteger("size", packet_size);
  34   return dict;
  35 }
  36
  37 base::Value* NetLogQuicPacketSentCallback(
  38     QuicPacketSequenceNumber sequence_number,
  39     EncryptionLevel level,
  40     size_t packet_size,
  41     WriteResult result,
  42     NetLog::LogLevel /* log_level */) {
  43   base::DictionaryValue* dict = new base::DictionaryValue();
  44   dict->SetInteger("encryption_level", level);
  45   dict->SetString("packet_sequence_number",
  46                   base::Uint64ToString(sequence_number));
  47   dict->SetInteger("size", packet_size);
  48   if (result.status != WRITE_STATUS_OK) {
  49     dict->SetInteger("net_error", result.error_code);
  50   }
  51   return dict;
  52 }
  53
  54 base::Value* NetLogQuicPacketRetransmittedCallback(
  55     QuicPacketSequenceNumber old_sequence_number,
  56     QuicPacketSequenceNumber new_sequence_number,
  57     NetLog::LogLevel /* log_level */) {
  58  base::DictionaryValue* dict = new base::DictionaryValue();
  59  dict->SetString("old_packet_sequence_number",
  60                  base::Uint64ToString(old_sequence_number));
  61  dict->SetString("new_packet_sequence_number",
  62                  base::Uint64ToString(new_sequence_number));
  63  return dict;
  64 }
  65
  66 base::Value* NetLogQuicPacketHeaderCallback(const QuicPacketHeader* header,
  67                                             NetLog::LogLevel /* log_level */) {
  68   base::DictionaryValue* dict = new base::DictionaryValue();
  69   dict->SetString("guid",
  70                   base::Uint64ToString(header->public_header.guid));
  71   dict->SetInteger("reset_flag", header->public_header.reset_flag);
  72   dict->SetInteger("version_flag", header->public_header.version_flag);
  73   dict->SetString("packet_sequence_number",
  74                   base::Uint64ToString(header->packet_sequence_number));
  75   dict->SetInteger("entropy_flag", header->entropy_flag);
  76   dict->SetInteger("fec_flag", header->fec_flag);
  77   dict->SetInteger("fec_group", header->fec_group);
  78   return dict;
  79 }
  80
  81 base::Value* NetLogQuicStreamFrameCallback(const QuicStreamFrame* frame,
  82                                            NetLog::LogLevel /* log_level */) {
  83   base::DictionaryValue* dict = new base::DictionaryValue();
  84   dict->SetInteger("stream_id", frame->stream_id);
  85   dict->SetBoolean("fin", frame->fin);
  86   dict->SetString("offset", base::Uint64ToString(frame->offset));
  87   dict->SetInteger("length", frame->data.TotalBufferSize());
  88   return dict;
  89 }
  90
  91 base::Value* NetLogQuicAckFrameCallback(const QuicAckFrame* frame,
  92                                         NetLog::LogLevel /* log_level */) {
  93   base::DictionaryValue* dict = new base::DictionaryValue();
  94   base::DictionaryValue* sent_info = new base::DictionaryValue();
  95   dict->Set("sent_info", sent_info);
  96   sent_info->SetString("least_unacked",
  97                        base::Uint64ToString(frame->sent_info.least_unacked));
  98   base::DictionaryValue* received_info = new base::DictionaryValue();
  99   dict->Set("received_info", received_info);
 100   received_info->SetString(
 101       "largest_observed",
 102       base::Uint64ToString(frame->received_info.largest_observed));
 103   received_info->SetBoolean("truncated", frame->received_info.is_truncated);
 104   base::ListValue* missing = new base::ListValue();
 105   received_info->Set("missing_packets", missing);
 106   const SequenceNumberSet& missing_packets =
 107       frame->received_info.missing_packets;
 108   for (SequenceNumberSet::const_iterator it = missing_packets.begin();
 109        it != missing_packets.end(); ++it) {
 110     missing->AppendString(base::Uint64ToString(*it));
 111   }
 112   return dict;
 113 }
 114
 115 base::Value* NetLogQuicCongestionFeedbackFrameCallback(
 116     const QuicCongestionFeedbackFrame* frame,
 117     NetLog::LogLevel /* log_level */) {
 118   base::DictionaryValue* dict = new base::DictionaryValue();
 119   switch (frame->type) {
 120     case kInterArrival: {
 121       dict->SetString("type", "InterArrival");
 122       base::ListValue* received = new base::ListValue();
 123       dict->Set("received_packets", received);
 124       for (TimeMap::const_iterator it =
 125                frame->inter_arrival.received_packet_times.begin();
 126            it != frame->inter_arrival.received_packet_times.end(); ++it) {
 127         std::string value = base::Uint64ToString(it->first) + "@" +
 128             base::Uint64ToString(it->second.ToDebuggingValue());
 129         received->AppendString(value);
 130       }
 131       break;
 132     }
 133     case kFixRate:
 134       dict->SetString("type", "FixRate");
 135       dict->SetInteger("bitrate_in_bytes_per_second",
 136                        frame->fix_rate.bitrate.ToBytesPerSecond());
 137       break;
 138     case kTCP:
 139       dict->SetString("type", "TCP");
 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* NetLogQuicWindowUpdateFrameCallback(
 167     const QuicWindowUpdateFrame* frame,
 168     NetLog::LogLevel /* log_level */) {
 169   base::DictionaryValue* dict = new base::DictionaryValue();
 170   dict->SetInteger("stream_id", frame->stream_id);
 171   dict->SetString("byte_offset", base::Uint64ToString(frame->byte_offset));
 172   return dict;
 173 }
 174
 175 base::Value* NetLogQuicBlockedFrameCallback(
 176     const QuicBlockedFrame* frame,
 177     NetLog::LogLevel /* log_level */) {
 178   base::DictionaryValue* dict = new base::DictionaryValue();
 179   dict->SetInteger("stream_id", frame->stream_id);
 180   return dict;
 181 }
 182
 183 base::Value* NetLogQuicStopWaitingFrameCallback(
 184     const QuicStopWaitingFrame* frame,
 185     NetLog::LogLevel /* log_level */) {
 186   base::DictionaryValue* dict = new base::DictionaryValue();
 187   base::DictionaryValue* sent_info = new base::DictionaryValue();
 188   dict->Set("sent_info", sent_info);
 189   sent_info->SetString("least_unacked",
 190                        base::Uint64ToString(frame->least_unacked));
 191   return dict;
 192 }
 193
 194 base::Value* NetLogQuicVersionNegotiationPacketCallback(
 195     const QuicVersionNegotiationPacket* packet,
 196     NetLog::LogLevel /* log_level */) {
 197   base::DictionaryValue* dict = new base::DictionaryValue();
 198   base::ListValue* versions = new base::ListValue();
 199   dict->Set("versions", versions);
 200   for (QuicVersionVector::const_iterator it = packet->versions.begin();
 201        it != packet->versions.end(); ++it) {
 202     versions->AppendString(QuicVersionToString(*it));
 203   }
 204   return dict;
 205 }
 206
 207 base::Value* NetLogQuicCryptoHandshakeMessageCallback(
 208     const CryptoHandshakeMessage* message,
 209     NetLog::LogLevel /* log_level */) {
 210   base::DictionaryValue* dict = new base::DictionaryValue();
 211   dict->SetString("quic_crypto_handshake_message", message->DebugString());
 212   return dict;
 213 }
 214
 215 base::Value* NetLogQuicOnConnectionClosedCallback(
 216     QuicErrorCode error,
 217     bool from_peer,
 218     NetLog::LogLevel /* log_level */) {
 219   base::DictionaryValue* dict = new base::DictionaryValue();
 220   dict->SetInteger("quic_error", error);
 221   dict->SetBoolean("from_peer", from_peer);
 222   return dict;
 223 }
 224
 225 void UpdatePacketGapSentHistogram(size_t num_consecutive_missing_packets) {
 226   UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapSent",
 227                        num_consecutive_missing_packets);
 228 }
 229
 230 void UpdatePublicResetAddressMismatchHistogram(
 231     const IPEndPoint& server_hello_address,
 232     const IPEndPoint& public_reset_address) {
 233   int sample = GetAddressMismatch(server_hello_address, public_reset_address);
 234   // We are seemingly talking to an older server that does not support the
 235   // feature, so we can't report the results in the histogram.
 236   if (sample < 0) {
 237     return;
 238   }
 239   UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.PublicResetAddressMismatch",
 240                             sample, QUIC_ADDRESS_MISMATCH_MAX);
 241 }
 242
 243 }  // namespace
 244
 245 QuicConnectionLogger::QuicConnectionLogger(const BoundNetLog& net_log)
 246     : net_log_(net_log),
 247       last_received_packet_sequence_number_(0),
 248       largest_received_packet_sequence_number_(0),
 249       largest_received_missing_packet_sequence_number_(0),
 250       out_of_order_recieved_packet_count_(0),
 251       num_truncated_acks_sent_(0),
 252       num_truncated_acks_received_(0) {
 253 }
 254
 255 QuicConnectionLogger::~QuicConnectionLogger() {
 256   UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderPacketsReceived",
 257                        out_of_order_recieved_packet_count_);
 258   UMA_HISTOGRAM_COUNTS("Net.QuicSession.TruncatedAcksSent",
 259                        num_truncated_acks_sent_);
 260   UMA_HISTOGRAM_COUNTS("Net.QuicSession.TruncatedAcksReceived",
 261                        num_truncated_acks_received_);
 262 }
 263
 264 void QuicConnectionLogger::OnFrameAddedToPacket(const QuicFrame& frame) {
 265   switch (frame.type) {
 266     case PADDING_FRAME:
 267       break;
 268     case STREAM_FRAME:
 269       net_log_.AddEvent(
 270           NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_SENT,
 271           base::Bind(&NetLogQuicStreamFrameCallback, frame.stream_frame));
 272       break;
 273     case ACK_FRAME:
 274       net_log_.AddEvent(
 275           NetLog::TYPE_QUIC_SESSION_ACK_FRAME_SENT,
 276           base::Bind(&NetLogQuicAckFrameCallback, frame.ack_frame));
 277       if (frame.ack_frame->received_info.is_truncated)
 278         ++num_truncated_acks_sent_;
 279       break;
 280     case CONGESTION_FEEDBACK_FRAME:
 281       net_log_.AddEvent(
 282           NetLog::TYPE_QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_SENT,
 283           base::Bind(&NetLogQuicCongestionFeedbackFrameCallback,
 284                      frame.congestion_feedback_frame));
 285       break;
 286     case RST_STREAM_FRAME:
 287       UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeClient",
 288                                   frame.rst_stream_frame->error_code);
 289       net_log_.AddEvent(
 290           NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_SENT,
 291           base::Bind(&NetLogQuicRstStreamFrameCallback,
 292                      frame.rst_stream_frame));
 293       break;
 294     case CONNECTION_CLOSE_FRAME:
 295       net_log_.AddEvent(
 296           NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_SENT,
 297           base::Bind(&NetLogQuicConnectionCloseFrameCallback,
 298                      frame.connection_close_frame));
 299       break;
 300     case GOAWAY_FRAME:
 301       break;
 302     case WINDOW_UPDATE_FRAME:
 303       net_log_.AddEvent(
 304           NetLog::TYPE_QUIC_SESSION_WINDOW_UPDATE_FRAME_SENT,
 305           base::Bind(&NetLogQuicWindowUpdateFrameCallback,
 306                      frame.window_update_frame));
 307       break;
 308     case BLOCKED_FRAME:
 309       net_log_.AddEvent(
 310           NetLog::TYPE_QUIC_SESSION_BLOCKED_FRAME_SENT,
 311           base::Bind(&NetLogQuicBlockedFrameCallback,
 312                      frame.blocked_frame));
 313       break;
 314     case STOP_WAITING_FRAME:
 315       net_log_.AddEvent(
 316           NetLog::TYPE_QUIC_SESSION_STOP_WAITING_FRAME_SENT,
 317           base::Bind(&NetLogQuicStopWaitingFrameCallback,
 318                      frame.stop_waiting_frame));
 319       break;
 320     default:
 321       DCHECK(false) << "Illegal frame type: " << frame.type;
 322   }
 323 }
 324
 325 void QuicConnectionLogger::OnPacketSent(
 326     QuicPacketSequenceNumber sequence_number,
 327     EncryptionLevel level,
 328     const QuicEncryptedPacket& packet,
 329     WriteResult result) {
 330   net_log_.AddEvent(
 331       NetLog::TYPE_QUIC_SESSION_PACKET_SENT,
 332       base::Bind(&NetLogQuicPacketSentCallback, sequence_number, level,
 333                  packet.length(), result));
 334 }
 335
 336 void QuicConnectionLogger:: OnPacketRetransmitted(
 337       QuicPacketSequenceNumber old_sequence_number,
 338       QuicPacketSequenceNumber new_sequence_number) {
 339   net_log_.AddEvent(
 340       NetLog::TYPE_QUIC_SESSION_PACKET_RETRANSMITTED,
 341       base::Bind(&NetLogQuicPacketRetransmittedCallback,
 342                  old_sequence_number, new_sequence_number));
 343 }
 344
 345 void QuicConnectionLogger::OnPacketReceived(const IPEndPoint& self_address,
 346                                             const IPEndPoint& peer_address,
 347                                             const QuicEncryptedPacket& packet) {
 348   net_log_.AddEvent(
 349       NetLog::TYPE_QUIC_SESSION_PACKET_RECEIVED,
 350       base::Bind(&NetLogQuicPacketCallback, &self_address, &peer_address,
 351                  packet.length()));
 352 }
 353
 354 void QuicConnectionLogger::OnProtocolVersionMismatch(
 355     QuicVersion received_version) {
 356   // TODO(rtenneti): Add logging.
 357 }
 358
 359 void QuicConnectionLogger::OnPacketHeader(const QuicPacketHeader& header) {
 360   net_log_.AddEvent(
 361       NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_RECEIVED,
 362       base::Bind(&NetLogQuicPacketHeaderCallback, &header));
 363   if (largest_received_packet_sequence_number_ <
 364       header.packet_sequence_number) {
 365     QuicPacketSequenceNumber delta = header.packet_sequence_number -
 366         largest_received_packet_sequence_number_;
 367     if (delta > 1) {
 368       // There is a gap between the largest packet previously received and
 369       // the current packet.  This indicates either loss, or out-of-order
 370       // delivery.
 371       UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapReceived", delta - 1);
 372     }
 373     largest_received_packet_sequence_number_ = header.packet_sequence_number;
 374   }
 375   if (header.packet_sequence_number < last_received_packet_sequence_number_) {
 376     ++out_of_order_recieved_packet_count_;
 377     UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderGapReceived",
 378                          last_received_packet_sequence_number_ -
 379                              header.packet_sequence_number);
 380   }
 381   last_received_packet_sequence_number_ = header.packet_sequence_number;
 382 }
 383
 384 void QuicConnectionLogger::OnStreamFrame(const QuicStreamFrame& frame) {
 385   net_log_.AddEvent(
 386       NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_RECEIVED,
 387       base::Bind(&NetLogQuicStreamFrameCallback, &frame));
 388 }
 389
 390 void QuicConnectionLogger::OnAckFrame(const QuicAckFrame& frame) {
 391   net_log_.AddEvent(
 392       NetLog::TYPE_QUIC_SESSION_ACK_FRAME_RECEIVED,
 393       base::Bind(&NetLogQuicAckFrameCallback, &frame));
 394
 395   if (frame.received_info.is_truncated)
 396     ++num_truncated_acks_received_;
 397
 398   if (frame.received_info.missing_packets.empty())
 399     return;
 400
 401   SequenceNumberSet missing_packets = frame.received_info.missing_packets;
 402   SequenceNumberSet::const_iterator it = missing_packets.lower_bound(
 403       largest_received_missing_packet_sequence_number_);
 404   if (it == missing_packets.end())
 405     return;
 406
 407   if (*it == largest_received_missing_packet_sequence_number_) {
 408     ++it;
 409     if (it == missing_packets.end())
 410       return;
 411   }
 412   // Scan through the list and log consecutive ranges of missing packets.
 413   size_t num_consecutive_missing_packets = 0;
 414   QuicPacketSequenceNumber previous_missing_packet = *it - 1;
 415   while (it != missing_packets.end()) {
 416     if (previous_missing_packet == *it - 1) {
 417       ++num_consecutive_missing_packets;
 418     } else {
 419       DCHECK_NE(0u, num_consecutive_missing_packets);
 420       UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
 421       // Make sure this packet it included in the count.
 422       num_consecutive_missing_packets = 1;
 423     }
 424     previous_missing_packet = *it;
 425     ++it;
 426   }
 427   if (num_consecutive_missing_packets != 0) {
 428     UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
 429   }
 430   largest_received_missing_packet_sequence_number_ =
 431         *missing_packets.rbegin();
 432 }
 433
 434 void QuicConnectionLogger::OnCongestionFeedbackFrame(
 435     const QuicCongestionFeedbackFrame& frame) {
 436   net_log_.AddEvent(
 437       NetLog::TYPE_QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_RECEIVED,
 438       base::Bind(&NetLogQuicCongestionFeedbackFrameCallback, &frame));
 439 }
 440
 441 void QuicConnectionLogger::OnStopWaitingFrame(
 442     const QuicStopWaitingFrame& frame) {
 443   net_log_.AddEvent(
 444       NetLog::TYPE_QUIC_SESSION_STOP_WAITING_FRAME_RECEIVED,
 445       base::Bind(&NetLogQuicStopWaitingFrameCallback, &frame));
 446 }
 447
 448 void QuicConnectionLogger::OnRstStreamFrame(const QuicRstStreamFrame& frame) {
 449   UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeServer",
 450                               frame.error_code);
 451   net_log_.AddEvent(
 452       NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_RECEIVED,
 453       base::Bind(&NetLogQuicRstStreamFrameCallback, &frame));
 454 }
 455
 456 void QuicConnectionLogger::OnConnectionCloseFrame(
 457     const QuicConnectionCloseFrame& frame) {
 458   net_log_.AddEvent(
 459       NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_RECEIVED,
 460       base::Bind(&NetLogQuicConnectionCloseFrameCallback, &frame));
 461 }
 462
 463 void QuicConnectionLogger::OnPublicResetPacket(
 464     const QuicPublicResetPacket& packet) {
 465   net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PUBLIC_RESET_PACKET_RECEIVED);
 466   UpdatePublicResetAddressMismatchHistogram(client_address_,
 467                                             packet.client_address);
 468 }
 469
 470 void QuicConnectionLogger::OnVersionNegotiationPacket(
 471     const QuicVersionNegotiationPacket& packet) {
 472   net_log_.AddEvent(
 473       NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATION_PACKET_RECEIVED,
 474       base::Bind(&NetLogQuicVersionNegotiationPacketCallback, &packet));
 475 }
 476
 477 void QuicConnectionLogger::OnRevivedPacket(
 478     const QuicPacketHeader& revived_header,
 479     base::StringPiece payload) {
 480   net_log_.AddEvent(
 481       NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_REVIVED,
 482       base::Bind(&NetLogQuicPacketHeaderCallback, &revived_header));
 483 }
 484
 485 void QuicConnectionLogger::OnCryptoHandshakeMessageReceived(
 486     const CryptoHandshakeMessage& message) {
 487   net_log_.AddEvent(
 488       NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_RECEIVED,
 489       base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
 490
 491   if (message.tag() == kSHLO) {
 492     StringPiece address;
 493     QuicSocketAddressCoder decoder;
 494     if (message.GetStringPiece(kCADR, &address) &&
 495         decoder.Decode(address.data(), address.size())) {
 496       client_address_ = IPEndPoint(decoder.ip(), decoder.port());
 497     }
 498   }
 499 }
 500
 501 void QuicConnectionLogger::OnCryptoHandshakeMessageSent(
 502     const CryptoHandshakeMessage& message) {
 503   net_log_.AddEvent(
 504       NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_SENT,
 505       base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
 506 }
 507
 508 void QuicConnectionLogger::OnConnectionClosed(QuicErrorCode error,
 509                                               bool from_peer) {
 510   net_log_.AddEvent(
 511       NetLog::TYPE_QUIC_SESSION_CLOSED,
 512       base::Bind(&NetLogQuicOnConnectionClosedCallback, error, from_peer));
 513 }
 514
 515 void QuicConnectionLogger::OnSuccessfulVersionNegotiation(
 516     const QuicVersion& version) {
 517   string quic_version = QuicVersionToString(version);
 518   net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATED,
 519                     NetLog::StringCallback("version", &quic_version));
 520 }
 521
 522 }  // namespace net