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 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 434
