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/strings/string_number_conversions.h" 11 #include "base/values.h" 12 #include "net/base/net_log.h" 13 14 namespace net { 15 16 namespace { 17 18 base::Value* NetLogQuicPacketCallback(const IPEndPoint* self_address, 19 const IPEndPoint* peer_address, 20 size_t packet_size, 21 NetLog::LogLevel /* log_level */) { 22 base::DictionaryValue* dict = new base::DictionaryValue(); 23 dict->SetString("self_address", self_address->ToString()); 24 dict->SetString("peer_address", peer_address->ToString()); 25 dict->SetInteger("size", packet_size); 26 return dict; 27 } 28 29 base::Value* NetLogQuicPacketSentCallback( 30 QuicPacketSequenceNumber sequence_number, 31 EncryptionLevel level, 32 size_t packet_size, 33 int rv, 34 NetLog::LogLevel /* log_level */) { 35 base::DictionaryValue* dict = new base::DictionaryValue(); 36 dict->SetInteger("encryption_level", level); 37 dict->SetString("packet_sequence_number", 38 base::Uint64ToString(sequence_number)); 39 dict->SetInteger("size", packet_size); 40 if (rv < 0) { 41 dict->SetInteger("net_error", rv); 42 } 43 return dict; 44 } 45 46 base::Value* NetLogQuicPacketHeaderCallback(const QuicPacketHeader* header, 47 NetLog::LogLevel /* log_level */) { 48 base::DictionaryValue* dict = new base::DictionaryValue(); 49 dict->SetString("guid", 50 base::Uint64ToString(header->public_header.guid)); 51 dict->SetInteger("reset_flag", header->public_header.reset_flag); 52 dict->SetInteger("version_flag", header->public_header.version_flag); 53 dict->SetString("packet_sequence_number", 54 base::Uint64ToString(header->packet_sequence_number)); 55 dict->SetInteger("entropy_flag", header->entropy_flag); 56 dict->SetInteger("fec_flag", header->fec_flag); 57 dict->SetInteger("fec_group", header->fec_group); 58 return dict; 59 } 60 61 base::Value* NetLogQuicStreamFrameCallback(const QuicStreamFrame* frame, 62 NetLog::LogLevel /* log_level */) { 63 base::DictionaryValue* dict = new base::DictionaryValue(); 64 dict->SetInteger("stream_id", frame->stream_id); 65 dict->SetBoolean("fin", frame->fin); 66 dict->SetString("offset", base::Uint64ToString(frame->offset)); 67 dict->SetInteger("length", frame->data.length()); 68 return dict; 69 } 70 71 base::Value* NetLogQuicAckFrameCallback(const QuicAckFrame* frame, 72 NetLog::LogLevel /* log_level */) { 73 base::DictionaryValue* dict = new base::DictionaryValue(); 74 base::DictionaryValue* sent_info = new base::DictionaryValue(); 75 dict->Set("sent_info", sent_info); 76 sent_info->SetString("least_unacked", 77 base::Uint64ToString(frame->sent_info.least_unacked)); 78 base::DictionaryValue* received_info = new base::DictionaryValue(); 79 dict->Set("received_info", received_info); 80 received_info->SetString( 81 "largest_observed", 82 base::Uint64ToString(frame->received_info.largest_observed)); 83 base::ListValue* missing = new base::ListValue(); 84 received_info->Set("missing_packets", missing); 85 const SequenceNumberSet& missing_packets = 86 frame->received_info.missing_packets; 87 for (SequenceNumberSet::const_iterator it = missing_packets.begin(); 88 it != missing_packets.end(); ++it) { 89 missing->Append(new base::StringValue(base::Uint64ToString(*it))); 90 } 91 return dict; 92 } 93 94 base::Value* NetLogQuicCongestionFeedbackFrameCallback( 95 const QuicCongestionFeedbackFrame* frame, 96 NetLog::LogLevel /* log_level */) { 97 base::DictionaryValue* dict = new base::DictionaryValue(); 98 switch (frame->type) { 99 case kInterArrival: { 100 dict->SetString("type", "InterArrival"); 101 dict->SetInteger("accumulated_number_of_lost_packets", 102 frame->inter_arrival.accumulated_number_of_lost_packets); 103 base::ListValue* received = new base::ListValue(); 104 dict->Set("received_packets", received); 105 for (TimeMap::const_iterator it = 106 frame->inter_arrival.received_packet_times.begin(); 107 it != frame->inter_arrival.received_packet_times.end(); ++it) { 108 std::string value = base::Uint64ToString(it->first) + "@" + 109 base::Uint64ToString(it->second.ToDebuggingValue()); 110 received->Append(new base::StringValue(value)); 111 } 112 break; 113 } 114 case kFixRate: 115 dict->SetString("type", "FixRate"); 116 dict->SetInteger("bitrate_in_bytes_per_second", 117 frame->fix_rate.bitrate.ToBytesPerSecond()); 118 break; 119 case kTCP: 120 dict->SetString("type", "TCP"); 121 dict->SetInteger("accumulated_number_of_lost_packets", 122 frame->tcp.accumulated_number_of_lost_packets); 123 dict->SetInteger("receive_window", frame->tcp.receive_window); 124 break; 125 } 126 127 return dict; 128 } 129 130 base::Value* NetLogQuicRstStreamFrameCallback( 131 const QuicRstStreamFrame* frame, 132 NetLog::LogLevel /* log_level */) { 133 base::DictionaryValue* dict = new base::DictionaryValue(); 134 dict->SetInteger("stream_id", frame->stream_id); 135 dict->SetInteger("quic_rst_stream_error", frame->error_code); 136 dict->SetString("details", frame->error_details); 137 return dict; 138 } 139 140 base::Value* NetLogQuicConnectionCloseFrameCallback( 141 const QuicConnectionCloseFrame* frame, 142 NetLog::LogLevel /* log_level */) { 143 base::DictionaryValue* dict = new base::DictionaryValue(); 144 dict->SetInteger("quic_error", frame->error_code); 145 dict->SetString("details", frame->error_details); 146 return dict; 147 } 148 149 void UpdatePacketGapSentHistogram(size_t num_consecutive_missing_packets) { 150 UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapSent", 151 num_consecutive_missing_packets); 152 } 153 154 } // namespace 155 156 QuicConnectionLogger::QuicConnectionLogger(const BoundNetLog& net_log) 157 : net_log_(net_log), 158 last_received_packet_sequence_number_(0), 159 largest_received_packet_sequence_number_(0), 160 largest_received_missing_packet_sequence_number_(0), 161 out_of_order_recieved_packet_count_(0) { 162 } 163 164 QuicConnectionLogger::~QuicConnectionLogger() { 165 UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderPacketsReceived", 166 out_of_order_recieved_packet_count_); 167 } 168 169 void QuicConnectionLogger::OnFrameAddedToPacket(const QuicFrame& frame) { 170 switch (frame.type) { 171 case PADDING_FRAME: 172 break; 173 case STREAM_FRAME: 174 net_log_.AddEvent( 175 NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_SENT, 176 base::Bind(&NetLogQuicStreamFrameCallback, frame.stream_frame)); 177 break; 178 case ACK_FRAME: 179 net_log_.AddEvent( 180 NetLog::TYPE_QUIC_SESSION_ACK_FRAME_SENT, 181 base::Bind(&NetLogQuicAckFrameCallback, frame.ack_frame)); 182 break; 183 case CONGESTION_FEEDBACK_FRAME: 184 net_log_.AddEvent( 185 NetLog::TYPE_QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_SENT, 186 base::Bind(&NetLogQuicCongestionFeedbackFrameCallback, 187 frame.congestion_feedback_frame)); 188 break; 189 case RST_STREAM_FRAME: 190 net_log_.AddEvent( 191 NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_SENT, 192 base::Bind(&NetLogQuicRstStreamFrameCallback, 193 frame.rst_stream_frame)); 194 break; 195 case CONNECTION_CLOSE_FRAME: 196 net_log_.AddEvent( 197 NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_SENT, 198 base::Bind(&NetLogQuicConnectionCloseFrameCallback, 199 frame.connection_close_frame)); 200 break; 201 case GOAWAY_FRAME: 202 break; 203 default: 204 DCHECK(false) << "Illegal frame type: " << frame.type; 205 } 206 } 207 208 void QuicConnectionLogger::OnPacketSent( 209 QuicPacketSequenceNumber sequence_number, 210 EncryptionLevel level, 211 const QuicEncryptedPacket& packet, 212 int rv) { 213 net_log_.AddEvent( 214 NetLog::TYPE_QUIC_SESSION_PACKET_SENT, 215 base::Bind(&NetLogQuicPacketSentCallback, sequence_number, level, 216 packet.length(), rv)); 217 } 218 219 void QuicConnectionLogger::OnPacketReceived(const IPEndPoint& self_address, 220 const IPEndPoint& peer_address, 221 const QuicEncryptedPacket& packet) { 222 net_log_.AddEvent( 223 NetLog::TYPE_QUIC_SESSION_PACKET_RECEIVED, 224 base::Bind(&NetLogQuicPacketCallback, &self_address, &peer_address, 225 packet.length())); 226 } 227 228 void QuicConnectionLogger::OnProtocolVersionMismatch( 229 QuicVersion received_version) { 230 // TODO(rtenneti): Add logging. 231 } 232 233 void QuicConnectionLogger::OnPacketHeader(const QuicPacketHeader& header) { 234 net_log_.AddEvent( 235 NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_RECEIVED, 236 base::Bind(&NetLogQuicPacketHeaderCallback, &header)); 237 if (largest_received_packet_sequence_number_ < 238 header.packet_sequence_number) { 239 QuicPacketSequenceNumber delta = header.packet_sequence_number - 240 largest_received_packet_sequence_number_; 241 if (delta > 1) { 242 // There is a gap between the largest packet previously received and 243 // the current packet. This indicates either loss, or out-of-order 244 // delivery. 245 UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapReceived", delta - 1); 246 } 247 largest_received_packet_sequence_number_ = header.packet_sequence_number; 248 } 249 if (header.packet_sequence_number < last_received_packet_sequence_number_) { 250 ++out_of_order_recieved_packet_count_; 251 } 252 last_received_packet_sequence_number_ = header.packet_sequence_number; 253 } 254 255 void QuicConnectionLogger::OnStreamFrame(const QuicStreamFrame& frame) { 256 net_log_.AddEvent( 257 NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_RECEIVED, 258 base::Bind(&NetLogQuicStreamFrameCallback, &frame)); 259 } 260 261 void QuicConnectionLogger::OnAckFrame(const QuicAckFrame& frame) { 262 net_log_.AddEvent( 263 NetLog::TYPE_QUIC_SESSION_ACK_FRAME_RECEIVED, 264 base::Bind(&NetLogQuicAckFrameCallback, &frame)); 265 266 if (frame.received_info.missing_packets.empty()) 267 return; 268 269 SequenceNumberSet missing_packets = frame.received_info.missing_packets; 270 SequenceNumberSet::const_iterator it = missing_packets.lower_bound( 271 largest_received_missing_packet_sequence_number_); 272 if (it == missing_packets.end()) 273 return; 274 275 if (*it == largest_received_missing_packet_sequence_number_) { 276 ++it; 277 if (it == missing_packets.end()) 278 return; 279 } 280 // Scan through the list and log consecutive ranges of missing packets. 281 size_t num_consecutive_missing_packets = 0; 282 QuicPacketSequenceNumber previous_missing_packet = *it - 1; 283 while (it != missing_packets.end()) { 284 if (previous_missing_packet == *it - 1) { 285 ++num_consecutive_missing_packets; 286 } else { 287 DCHECK_NE(0u, num_consecutive_missing_packets); 288 UpdatePacketGapSentHistogram(num_consecutive_missing_packets); 289 // Make sure this packet it included in the count. 290 num_consecutive_missing_packets = 1; 291 } 292 previous_missing_packet = *it; 293 ++it; 294 } 295 if (num_consecutive_missing_packets != 0) { 296 UpdatePacketGapSentHistogram(num_consecutive_missing_packets); 297 } 298 largest_received_missing_packet_sequence_number_ = 299 *missing_packets.rbegin(); 300 } 301 302 void QuicConnectionLogger::OnCongestionFeedbackFrame( 303 const QuicCongestionFeedbackFrame& frame) { 304 net_log_.AddEvent( 305 NetLog::TYPE_QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_RECEIVED, 306 base::Bind(&NetLogQuicCongestionFeedbackFrameCallback, &frame)); 307 } 308 309 void QuicConnectionLogger::OnRstStreamFrame(const QuicRstStreamFrame& frame) { 310 net_log_.AddEvent( 311 NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_RECEIVED, 312 base::Bind(&NetLogQuicRstStreamFrameCallback, &frame)); 313 } 314 315 void QuicConnectionLogger::OnConnectionCloseFrame( 316 const QuicConnectionCloseFrame& frame) { 317 net_log_.AddEvent( 318 NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_RECEIVED, 319 base::Bind(&NetLogQuicConnectionCloseFrameCallback, &frame)); 320 } 321 322 void QuicConnectionLogger::OnPublicResetPacket( 323 const QuicPublicResetPacket& packet) { 324 } 325 326 void QuicConnectionLogger::OnVersionNegotiationPacket( 327 const QuicVersionNegotiationPacket& packet) { 328 } 329 330 void QuicConnectionLogger::OnRevivedPacket( 331 const QuicPacketHeader& revived_header, 332 base::StringPiece payload) { 333 } 334 335 } // namespace net 336
