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 906
