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/quic/crypto/crypto_handshake_message.h"
19 #include "net/quic/crypto/crypto_protocol.h"
20 #include "net/quic/quic_address_mismatch.h"
21 #include "net/quic/quic_socket_address_coder.h"
22
23 using base::StringPiece;
24 using std::string;
25
26 namespace net {
27
28 namespace {
29
30 // We have ranges-of-buckets in the cumulative histogram (covering 21 packet
31 // sequences) of length 2, 3, 4, ... 22.
32 // Hence the largest sample is bounded by the sum of those numbers.
33 const int kBoundingSampleInCumulativeHistogram = ((2 + 22) * 21) / 2;
34
NetLogQuicPacketCallback(const IPEndPoint * self_address,const IPEndPoint * peer_address,size_t packet_size,NetLog::LogLevel)35 base::Value* NetLogQuicPacketCallback(const IPEndPoint* self_address,
36 const IPEndPoint* peer_address,
37 size_t packet_size,
38 NetLog::LogLevel /* log_level */) {
39 base::DictionaryValue* dict = new base::DictionaryValue();
40 dict->SetString("self_address", self_address->ToString());
41 dict->SetString("peer_address", peer_address->ToString());
42 dict->SetInteger("size", packet_size);
43 return dict;
44 }
45
NetLogQuicPacketSentCallback(QuicPacketSequenceNumber sequence_number,EncryptionLevel level,TransmissionType transmission_type,size_t packet_size,WriteResult result,NetLog::LogLevel)46 base::Value* NetLogQuicPacketSentCallback(
47 QuicPacketSequenceNumber sequence_number,
48 EncryptionLevel level,
49 TransmissionType transmission_type,
50 size_t packet_size,
51 WriteResult result,
52 NetLog::LogLevel /* log_level */) {
53 base::DictionaryValue* dict = new base::DictionaryValue();
54 dict->SetInteger("encryption_level", level);
55 dict->SetInteger("transmission_type", transmission_type);
56 dict->SetString("packet_sequence_number",
57 base::Uint64ToString(sequence_number));
58 dict->SetInteger("size", packet_size);
59 if (result.status != WRITE_STATUS_OK) {
60 dict->SetInteger("net_error", result.error_code);
61 }
62 return dict;
63 }
64
NetLogQuicPacketRetransmittedCallback(QuicPacketSequenceNumber old_sequence_number,QuicPacketSequenceNumber new_sequence_number,NetLog::LogLevel)65 base::Value* NetLogQuicPacketRetransmittedCallback(
66 QuicPacketSequenceNumber old_sequence_number,
67 QuicPacketSequenceNumber new_sequence_number,
68 NetLog::LogLevel /* log_level */) {
69 base::DictionaryValue* dict = new base::DictionaryValue();
70 dict->SetString("old_packet_sequence_number",
71 base::Uint64ToString(old_sequence_number));
72 dict->SetString("new_packet_sequence_number",
73 base::Uint64ToString(new_sequence_number));
74 return dict;
75 }
76
NetLogQuicPacketHeaderCallback(const QuicPacketHeader * header,NetLog::LogLevel)77 base::Value* NetLogQuicPacketHeaderCallback(const QuicPacketHeader* header,
78 NetLog::LogLevel /* log_level */) {
79 base::DictionaryValue* dict = new base::DictionaryValue();
80 dict->SetString("connection_id",
81 base::Uint64ToString(header->public_header.connection_id));
82 dict->SetInteger("reset_flag", header->public_header.reset_flag);
83 dict->SetInteger("version_flag", header->public_header.version_flag);
84 dict->SetString("packet_sequence_number",
85 base::Uint64ToString(header->packet_sequence_number));
86 dict->SetInteger("entropy_flag", header->entropy_flag);
87 dict->SetInteger("fec_flag", header->fec_flag);
88 dict->SetInteger("fec_group", header->fec_group);
89 return dict;
90 }
91
NetLogQuicStreamFrameCallback(const QuicStreamFrame * frame,NetLog::LogLevel)92 base::Value* NetLogQuicStreamFrameCallback(const QuicStreamFrame* frame,
93 NetLog::LogLevel /* log_level */) {
94 base::DictionaryValue* dict = new base::DictionaryValue();
95 dict->SetInteger("stream_id", frame->stream_id);
96 dict->SetBoolean("fin", frame->fin);
97 dict->SetString("offset", base::Uint64ToString(frame->offset));
98 dict->SetInteger("length", frame->data.TotalBufferSize());
99 return dict;
100 }
101
NetLogQuicAckFrameCallback(const QuicAckFrame * frame,NetLog::LogLevel)102 base::Value* NetLogQuicAckFrameCallback(const QuicAckFrame* frame,
103 NetLog::LogLevel /* log_level */) {
104 base::DictionaryValue* dict = new base::DictionaryValue();
105 base::DictionaryValue* received_info = new base::DictionaryValue();
106 dict->Set("received_info", received_info);
107 received_info->SetString(
108 "largest_observed",
109 base::Uint64ToString(frame->received_info.largest_observed));
110 received_info->SetBoolean("truncated", frame->received_info.is_truncated);
111 base::ListValue* missing = new base::ListValue();
112 received_info->Set("missing_packets", missing);
113 const SequenceNumberSet& missing_packets =
114 frame->received_info.missing_packets;
115 for (SequenceNumberSet::const_iterator it = missing_packets.begin();
116 it != missing_packets.end(); ++it) {
117 missing->AppendString(base::Uint64ToString(*it));
118 }
119 return dict;
120 }
121
NetLogQuicCongestionFeedbackFrameCallback(const QuicCongestionFeedbackFrame * frame,NetLog::LogLevel)122 base::Value* NetLogQuicCongestionFeedbackFrameCallback(
123 const QuicCongestionFeedbackFrame* frame,
124 NetLog::LogLevel /* log_level */) {
125 base::DictionaryValue* dict = new base::DictionaryValue();
126 switch (frame->type) {
127 case kInterArrival: {
128 dict->SetString("type", "InterArrival");
129 base::ListValue* received = new base::ListValue();
130 dict->Set("received_packets", received);
131 for (TimeMap::const_iterator it =
132 frame->inter_arrival.received_packet_times.begin();
133 it != frame->inter_arrival.received_packet_times.end(); ++it) {
134 string value = base::Uint64ToString(it->first) + "@" +
135 base::Uint64ToString(it->second.ToDebuggingValue());
136 received->AppendString(value);
137 }
138 break;
139 }
140 case kFixRate:
141 dict->SetString("type", "FixRate");
142 dict->SetInteger("bitrate_in_bytes_per_second",
143 frame->fix_rate.bitrate.ToBytesPerSecond());
144 break;
145 case kTCP:
146 dict->SetString("type", "TCP");
147 dict->SetInteger("receive_window", frame->tcp.receive_window);
148 break;
149 case kTCPBBR:
150 dict->SetString("type", "TCPBBR");
151 // TODO(rtenneti): Add support for BBR.
152 break;
153 }
154
155 return dict;
156 }
157
NetLogQuicRstStreamFrameCallback(const QuicRstStreamFrame * frame,NetLog::LogLevel)158 base::Value* NetLogQuicRstStreamFrameCallback(
159 const QuicRstStreamFrame* frame,
160 NetLog::LogLevel /* log_level */) {
161 base::DictionaryValue* dict = new base::DictionaryValue();
162 dict->SetInteger("stream_id", frame->stream_id);
163 dict->SetInteger("quic_rst_stream_error", frame->error_code);
164 dict->SetString("details", frame->error_details);
165 return dict;
166 }
167
NetLogQuicConnectionCloseFrameCallback(const QuicConnectionCloseFrame * frame,NetLog::LogLevel)168 base::Value* NetLogQuicConnectionCloseFrameCallback(
169 const QuicConnectionCloseFrame* frame,
170 NetLog::LogLevel /* log_level */) {
171 base::DictionaryValue* dict = new base::DictionaryValue();
172 dict->SetInteger("quic_error", frame->error_code);
173 dict->SetString("details", frame->error_details);
174 return dict;
175 }
176
NetLogQuicWindowUpdateFrameCallback(const QuicWindowUpdateFrame * frame,NetLog::LogLevel)177 base::Value* NetLogQuicWindowUpdateFrameCallback(
178 const QuicWindowUpdateFrame* frame,
179 NetLog::LogLevel /* log_level */) {
180 base::DictionaryValue* dict = new base::DictionaryValue();
181 dict->SetInteger("stream_id", frame->stream_id);
182 dict->SetString("byte_offset", base::Uint64ToString(frame->byte_offset));
183 return dict;
184 }
185
NetLogQuicBlockedFrameCallback(const QuicBlockedFrame * frame,NetLog::LogLevel)186 base::Value* NetLogQuicBlockedFrameCallback(
187 const QuicBlockedFrame* frame,
188 NetLog::LogLevel /* log_level */) {
189 base::DictionaryValue* dict = new base::DictionaryValue();
190 dict->SetInteger("stream_id", frame->stream_id);
191 return dict;
192 }
193
NetLogQuicGoAwayFrameCallback(const QuicGoAwayFrame * frame,NetLog::LogLevel)194 base::Value* NetLogQuicGoAwayFrameCallback(
195 const QuicGoAwayFrame* frame,
196 NetLog::LogLevel /* log_level */) {
197 base::DictionaryValue* dict = new base::DictionaryValue();
198 dict->SetInteger("quic_error", frame->error_code);
199 dict->SetInteger("last_good_stream_id", frame->last_good_stream_id);
200 dict->SetString("reason_phrase", frame->reason_phrase);
201 return dict;
202 }
203
NetLogQuicStopWaitingFrameCallback(const QuicStopWaitingFrame * frame,NetLog::LogLevel)204 base::Value* NetLogQuicStopWaitingFrameCallback(
205 const QuicStopWaitingFrame* frame,
206 NetLog::LogLevel /* log_level */) {
207 base::DictionaryValue* dict = new base::DictionaryValue();
208 base::DictionaryValue* sent_info = new base::DictionaryValue();
209 dict->Set("sent_info", sent_info);
210 sent_info->SetString("least_unacked",
211 base::Uint64ToString(frame->least_unacked));
212 return dict;
213 }
214
NetLogQuicVersionNegotiationPacketCallback(const QuicVersionNegotiationPacket * packet,NetLog::LogLevel)215 base::Value* NetLogQuicVersionNegotiationPacketCallback(
216 const QuicVersionNegotiationPacket* packet,
217 NetLog::LogLevel /* log_level */) {
218 base::DictionaryValue* dict = new base::DictionaryValue();
219 base::ListValue* versions = new base::ListValue();
220 dict->Set("versions", versions);
221 for (QuicVersionVector::const_iterator it = packet->versions.begin();
222 it != packet->versions.end(); ++it) {
223 versions->AppendString(QuicVersionToString(*it));
224 }
225 return dict;
226 }
227
NetLogQuicCryptoHandshakeMessageCallback(const CryptoHandshakeMessage * message,NetLog::LogLevel)228 base::Value* NetLogQuicCryptoHandshakeMessageCallback(
229 const CryptoHandshakeMessage* message,
230 NetLog::LogLevel /* log_level */) {
231 base::DictionaryValue* dict = new base::DictionaryValue();
232 dict->SetString("quic_crypto_handshake_message", message->DebugString());
233 return dict;
234 }
235
NetLogQuicOnConnectionClosedCallback(QuicErrorCode error,bool from_peer,NetLog::LogLevel)236 base::Value* NetLogQuicOnConnectionClosedCallback(
237 QuicErrorCode error,
238 bool from_peer,
239 NetLog::LogLevel /* log_level */) {
240 base::DictionaryValue* dict = new base::DictionaryValue();
241 dict->SetInteger("quic_error", error);
242 dict->SetBoolean("from_peer", from_peer);
243 return dict;
244 }
245
UpdatePacketGapSentHistogram(size_t num_consecutive_missing_packets)246 void UpdatePacketGapSentHistogram(size_t num_consecutive_missing_packets) {
247 UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapSent",
248 num_consecutive_missing_packets);
249 }
250
UpdatePublicResetAddressMismatchHistogram(const IPEndPoint & server_hello_address,const IPEndPoint & public_reset_address)251 void UpdatePublicResetAddressMismatchHistogram(
252 const IPEndPoint& server_hello_address,
253 const IPEndPoint& public_reset_address) {
254 int sample = GetAddressMismatch(server_hello_address, public_reset_address);
255 // We are seemingly talking to an older server that does not support the
256 // feature, so we can't report the results in the histogram.
257 if (sample < 0) {
258 return;
259 }
260 UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.PublicResetAddressMismatch2",
261 sample, QUIC_ADDRESS_MISMATCH_MAX);
262 }
263
GetConnectionDescriptionString()264 const char* GetConnectionDescriptionString() {
265 NetworkChangeNotifier::ConnectionType type =
266 NetworkChangeNotifier::GetConnectionType();
267 const char* description = NetworkChangeNotifier::ConnectionTypeToString(type);
268 // Most platforms don't distingish Wifi vs Etherenet, and call everything
269 // CONNECTION_UNKNOWN :-(. We'll tease out some details when we are on WiFi,
270 // and hopefully leave only ethernet (with no WiFi available) in the
271 // CONNECTION_UNKNOWN category. This *might* err if there is both ethernet,
272 // as well as WiFi, where WiFi was not being used that much.
273 // This function only seems usefully defined on Windows currently.
274 if (type == NetworkChangeNotifier::CONNECTION_UNKNOWN ||
275 type == NetworkChangeNotifier::CONNECTION_WIFI) {
276 WifiPHYLayerProtocol wifi_type = GetWifiPHYLayerProtocol();
277 switch (wifi_type) {
278 case WIFI_PHY_LAYER_PROTOCOL_NONE:
279 // No wifi support or no associated AP.
280 break;
281 case WIFI_PHY_LAYER_PROTOCOL_ANCIENT:
282 // An obsolete modes introduced by the original 802.11, e.g. IR, FHSS.
283 description = "CONNECTION_WIFI_ANCIENT";
284 break;
285 case WIFI_PHY_LAYER_PROTOCOL_A:
286 // 802.11a, OFDM-based rates.
287 description = "CONNECTION_WIFI_802.11a";
288 break;
289 case WIFI_PHY_LAYER_PROTOCOL_B:
290 // 802.11b, DSSS or HR DSSS.
291 description = "CONNECTION_WIFI_802.11b";
292 break;
293 case WIFI_PHY_LAYER_PROTOCOL_G:
294 // 802.11g, same rates as 802.11a but compatible with 802.11b.
295 description = "CONNECTION_WIFI_802.11g";
296 break;
297 case WIFI_PHY_LAYER_PROTOCOL_N:
298 // 802.11n, HT rates.
299 description = "CONNECTION_WIFI_802.11n";
300 break;
301 case WIFI_PHY_LAYER_PROTOCOL_UNKNOWN:
302 // Unclassified mode or failure to identify.
303 break;
304 }
305 }
306 return description;
307 }
308
309 // If |address| is an IPv4-mapped IPv6 address, returns ADDRESS_FAMILY_IPV4
310 // instead of ADDRESS_FAMILY_IPV6. Othewise, behaves like GetAddressFamily().
GetRealAddressFamily(const IPAddressNumber & address)311 AddressFamily GetRealAddressFamily(const IPAddressNumber& address) {
312 return IsIPv4Mapped(address) ? ADDRESS_FAMILY_IPV4 :
313 GetAddressFamily(address);
314 }
315
316 } // namespace
317
QuicConnectionLogger(const BoundNetLog & net_log)318 QuicConnectionLogger::QuicConnectionLogger(const BoundNetLog& net_log)
319 : net_log_(net_log),
320 last_received_packet_sequence_number_(0),
321 last_received_packet_size_(0),
322 largest_received_packet_sequence_number_(0),
323 largest_received_missing_packet_sequence_number_(0),
324 num_out_of_order_received_packets_(0),
325 num_packets_received_(0),
326 num_truncated_acks_sent_(0),
327 num_truncated_acks_received_(0),
328 num_frames_received_(0),
329 num_duplicate_frames_received_(0),
330 connection_description_(GetConnectionDescriptionString()) {
331 }
332
~QuicConnectionLogger()333 QuicConnectionLogger::~QuicConnectionLogger() {
334 UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderPacketsReceived",
335 num_out_of_order_received_packets_);
336 UMA_HISTOGRAM_COUNTS("Net.QuicSession.TruncatedAcksSent",
337 num_truncated_acks_sent_);
338 UMA_HISTOGRAM_COUNTS("Net.QuicSession.TruncatedAcksReceived",
339 num_truncated_acks_received_);
340 if (num_frames_received_ > 0) {
341 int duplicate_stream_frame_per_thousand =
342 num_duplicate_frames_received_ * 1000 / num_frames_received_;
343 if (num_packets_received_ < 100) {
344 UMA_HISTOGRAM_CUSTOM_COUNTS(
345 "Net.QuicSession.StreamFrameDuplicatedShortConnection",
346 duplicate_stream_frame_per_thousand, 1, 1000, 75);
347 } else {
348 UMA_HISTOGRAM_CUSTOM_COUNTS(
349 "Net.QuicSession.StreamFrameDuplicatedLongConnection",
350 duplicate_stream_frame_per_thousand, 1, 1000, 75);
351
352 }
353 }
354
355 RecordLossHistograms();
356 }
357
OnFrameAddedToPacket(const QuicFrame & frame)358 void QuicConnectionLogger::OnFrameAddedToPacket(const QuicFrame& frame) {
359 switch (frame.type) {
360 case PADDING_FRAME:
361 break;
362 case STREAM_FRAME:
363 net_log_.AddEvent(
364 NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_SENT,
365 base::Bind(&NetLogQuicStreamFrameCallback, frame.stream_frame));
366 break;
367 case ACK_FRAME:
368 net_log_.AddEvent(
369 NetLog::TYPE_QUIC_SESSION_ACK_FRAME_SENT,
370 base::Bind(&NetLogQuicAckFrameCallback, frame.ack_frame));
371 if (frame.ack_frame->received_info.is_truncated)
372 ++num_truncated_acks_sent_;
373 break;
374 case CONGESTION_FEEDBACK_FRAME:
375 net_log_.AddEvent(
376 NetLog::TYPE_QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_SENT,
377 base::Bind(&NetLogQuicCongestionFeedbackFrameCallback,
378 frame.congestion_feedback_frame));
379 break;
380 case RST_STREAM_FRAME:
381 UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeClient",
382 frame.rst_stream_frame->error_code);
383 net_log_.AddEvent(
384 NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_SENT,
385 base::Bind(&NetLogQuicRstStreamFrameCallback,
386 frame.rst_stream_frame));
387 break;
388 case CONNECTION_CLOSE_FRAME:
389 net_log_.AddEvent(
390 NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_SENT,
391 base::Bind(&NetLogQuicConnectionCloseFrameCallback,
392 frame.connection_close_frame));
393 break;
394 case GOAWAY_FRAME:
395 net_log_.AddEvent(
396 NetLog::TYPE_QUIC_SESSION_GOAWAY_FRAME_SENT,
397 base::Bind(&NetLogQuicGoAwayFrameCallback,
398 frame.goaway_frame));
399 break;
400 case WINDOW_UPDATE_FRAME:
401 net_log_.AddEvent(
402 NetLog::TYPE_QUIC_SESSION_WINDOW_UPDATE_FRAME_SENT,
403 base::Bind(&NetLogQuicWindowUpdateFrameCallback,
404 frame.window_update_frame));
405 break;
406 case BLOCKED_FRAME:
407 net_log_.AddEvent(
408 NetLog::TYPE_QUIC_SESSION_BLOCKED_FRAME_SENT,
409 base::Bind(&NetLogQuicBlockedFrameCallback,
410 frame.blocked_frame));
411 break;
412 case STOP_WAITING_FRAME:
413 net_log_.AddEvent(
414 NetLog::TYPE_QUIC_SESSION_STOP_WAITING_FRAME_SENT,
415 base::Bind(&NetLogQuicStopWaitingFrameCallback,
416 frame.stop_waiting_frame));
417 break;
418 case PING_FRAME:
419 // PingFrame has no contents to log, so just record that it was sent.
420 net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PING_FRAME_SENT);
421 break;
422 default:
423 DCHECK(false) << "Illegal frame type: " << frame.type;
424 }
425 }
426
OnPacketSent(QuicPacketSequenceNumber sequence_number,EncryptionLevel level,TransmissionType transmission_type,const QuicEncryptedPacket & packet,WriteResult result)427 void QuicConnectionLogger::OnPacketSent(
428 QuicPacketSequenceNumber sequence_number,
429 EncryptionLevel level,
430 TransmissionType transmission_type,
431 const QuicEncryptedPacket& packet,
432 WriteResult result) {
433 net_log_.AddEvent(
434 NetLog::TYPE_QUIC_SESSION_PACKET_SENT,
435 base::Bind(&NetLogQuicPacketSentCallback, sequence_number, level,
436 transmission_type, packet.length(), result));
437 }
438
OnPacketRetransmitted(QuicPacketSequenceNumber old_sequence_number,QuicPacketSequenceNumber new_sequence_number)439 void QuicConnectionLogger:: OnPacketRetransmitted(
440 QuicPacketSequenceNumber old_sequence_number,
441 QuicPacketSequenceNumber new_sequence_number) {
442 net_log_.AddEvent(
443 NetLog::TYPE_QUIC_SESSION_PACKET_RETRANSMITTED,
444 base::Bind(&NetLogQuicPacketRetransmittedCallback,
445 old_sequence_number, new_sequence_number));
446 }
447
OnPacketReceived(const IPEndPoint & self_address,const IPEndPoint & peer_address,const QuicEncryptedPacket & packet)448 void QuicConnectionLogger::OnPacketReceived(const IPEndPoint& self_address,
449 const IPEndPoint& peer_address,
450 const QuicEncryptedPacket& packet) {
451 if (local_address_from_self_.GetFamily() == ADDRESS_FAMILY_UNSPECIFIED) {
452 local_address_from_self_ = self_address;
453 UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.ConnectionTypeFromSelf",
454 GetRealAddressFamily(self_address.address()),
455 ADDRESS_FAMILY_LAST);
456 }
457
458 last_received_packet_size_ = packet.length();
459 net_log_.AddEvent(
460 NetLog::TYPE_QUIC_SESSION_PACKET_RECEIVED,
461 base::Bind(&NetLogQuicPacketCallback, &self_address, &peer_address,
462 packet.length()));
463 }
464
OnProtocolVersionMismatch(QuicVersion received_version)465 void QuicConnectionLogger::OnProtocolVersionMismatch(
466 QuicVersion received_version) {
467 // TODO(rtenneti): Add logging.
468 }
469
OnPacketHeader(const QuicPacketHeader & header)470 void QuicConnectionLogger::OnPacketHeader(const QuicPacketHeader& header) {
471 net_log_.AddEvent(
472 NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_RECEIVED,
473 base::Bind(&NetLogQuicPacketHeaderCallback, &header));
474 ++num_packets_received_;
475 if (largest_received_packet_sequence_number_ <
476 header.packet_sequence_number) {
477 QuicPacketSequenceNumber delta = header.packet_sequence_number -
478 largest_received_packet_sequence_number_;
479 if (delta > 1) {
480 // There is a gap between the largest packet previously received and
481 // the current packet. This indicates either loss, or out-of-order
482 // delivery.
483 UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapReceived", delta - 1);
484 }
485 largest_received_packet_sequence_number_ = header.packet_sequence_number;
486 }
487 if (header.packet_sequence_number < received_packets_.size())
488 received_packets_[header.packet_sequence_number] = true;
489 if (header.packet_sequence_number < last_received_packet_sequence_number_) {
490 ++num_out_of_order_received_packets_;
491 UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderGapReceived",
492 last_received_packet_sequence_number_ -
493 header.packet_sequence_number);
494 }
495 last_received_packet_sequence_number_ = header.packet_sequence_number;
496 }
497
OnStreamFrame(const QuicStreamFrame & frame)498 void QuicConnectionLogger::OnStreamFrame(const QuicStreamFrame& frame) {
499 net_log_.AddEvent(
500 NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_RECEIVED,
501 base::Bind(&NetLogQuicStreamFrameCallback, &frame));
502 }
503
OnAckFrame(const QuicAckFrame & frame)504 void QuicConnectionLogger::OnAckFrame(const QuicAckFrame& frame) {
505 net_log_.AddEvent(
506 NetLog::TYPE_QUIC_SESSION_ACK_FRAME_RECEIVED,
507 base::Bind(&NetLogQuicAckFrameCallback, &frame));
508
509 const size_t kApproximateLargestSoloAckBytes = 100;
510 if (last_received_packet_sequence_number_ < received_acks_.size() &&
511 last_received_packet_size_ < kApproximateLargestSoloAckBytes)
512 received_acks_[last_received_packet_sequence_number_] = true;
513
514 if (frame.received_info.is_truncated)
515 ++num_truncated_acks_received_;
516
517 if (frame.received_info.missing_packets.empty())
518 return;
519
520 SequenceNumberSet missing_packets = frame.received_info.missing_packets;
521 SequenceNumberSet::const_iterator it = missing_packets.lower_bound(
522 largest_received_missing_packet_sequence_number_);
523 if (it == missing_packets.end())
524 return;
525
526 if (*it == largest_received_missing_packet_sequence_number_) {
527 ++it;
528 if (it == missing_packets.end())
529 return;
530 }
531 // Scan through the list and log consecutive ranges of missing packets.
532 size_t num_consecutive_missing_packets = 0;
533 QuicPacketSequenceNumber previous_missing_packet = *it - 1;
534 while (it != missing_packets.end()) {
535 if (previous_missing_packet == *it - 1) {
536 ++num_consecutive_missing_packets;
537 } else {
538 DCHECK_NE(0u, num_consecutive_missing_packets);
539 UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
540 // Make sure this packet it included in the count.
541 num_consecutive_missing_packets = 1;
542 }
543 previous_missing_packet = *it;
544 ++it;
545 }
546 if (num_consecutive_missing_packets != 0) {
547 UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
548 }
549 largest_received_missing_packet_sequence_number_ =
550 *missing_packets.rbegin();
551 }
552
OnCongestionFeedbackFrame(const QuicCongestionFeedbackFrame & frame)553 void QuicConnectionLogger::OnCongestionFeedbackFrame(
554 const QuicCongestionFeedbackFrame& frame) {
555 net_log_.AddEvent(
556 NetLog::TYPE_QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_RECEIVED,
557 base::Bind(&NetLogQuicCongestionFeedbackFrameCallback, &frame));
558 }
559
OnStopWaitingFrame(const QuicStopWaitingFrame & frame)560 void QuicConnectionLogger::OnStopWaitingFrame(
561 const QuicStopWaitingFrame& frame) {
562 net_log_.AddEvent(
563 NetLog::TYPE_QUIC_SESSION_STOP_WAITING_FRAME_RECEIVED,
564 base::Bind(&NetLogQuicStopWaitingFrameCallback, &frame));
565 }
566
OnRstStreamFrame(const QuicRstStreamFrame & frame)567 void QuicConnectionLogger::OnRstStreamFrame(const QuicRstStreamFrame& frame) {
568 UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeServer",
569 frame.error_code);
570 net_log_.AddEvent(
571 NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_RECEIVED,
572 base::Bind(&NetLogQuicRstStreamFrameCallback, &frame));
573 }
574
OnConnectionCloseFrame(const QuicConnectionCloseFrame & frame)575 void QuicConnectionLogger::OnConnectionCloseFrame(
576 const QuicConnectionCloseFrame& frame) {
577 net_log_.AddEvent(
578 NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_RECEIVED,
579 base::Bind(&NetLogQuicConnectionCloseFrameCallback, &frame));
580 }
581
OnWindowUpdateFrame(const QuicWindowUpdateFrame & frame)582 void QuicConnectionLogger::OnWindowUpdateFrame(
583 const QuicWindowUpdateFrame& frame) {
584 net_log_.AddEvent(
585 NetLog::TYPE_QUIC_SESSION_WINDOW_UPDATE_FRAME_RECEIVED,
586 base::Bind(&NetLogQuicWindowUpdateFrameCallback, &frame));
587 }
588
OnBlockedFrame(const QuicBlockedFrame & frame)589 void QuicConnectionLogger::OnBlockedFrame(const QuicBlockedFrame& frame) {
590 net_log_.AddEvent(
591 NetLog::TYPE_QUIC_SESSION_BLOCKED_FRAME_RECEIVED,
592 base::Bind(&NetLogQuicBlockedFrameCallback, &frame));
593 }
594
OnGoAwayFrame(const QuicGoAwayFrame & frame)595 void QuicConnectionLogger::OnGoAwayFrame(const QuicGoAwayFrame& frame) {
596 net_log_.AddEvent(
597 NetLog::TYPE_QUIC_SESSION_GOAWAY_FRAME_RECEIVED,
598 base::Bind(&NetLogQuicGoAwayFrameCallback, &frame));
599 }
600
OnPingFrame(const QuicPingFrame & frame)601 void QuicConnectionLogger::OnPingFrame(const QuicPingFrame& frame) {
602 // PingFrame has no contents to log, so just record that it was received.
603 net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PING_FRAME_RECEIVED);
604 }
605
OnPublicResetPacket(const QuicPublicResetPacket & packet)606 void QuicConnectionLogger::OnPublicResetPacket(
607 const QuicPublicResetPacket& packet) {
608 net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PUBLIC_RESET_PACKET_RECEIVED);
609 UpdatePublicResetAddressMismatchHistogram(local_address_from_shlo_,
610 packet.client_address);
611 }
612
OnVersionNegotiationPacket(const QuicVersionNegotiationPacket & packet)613 void QuicConnectionLogger::OnVersionNegotiationPacket(
614 const QuicVersionNegotiationPacket& packet) {
615 net_log_.AddEvent(
616 NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATION_PACKET_RECEIVED,
617 base::Bind(&NetLogQuicVersionNegotiationPacketCallback, &packet));
618 }
619
OnRevivedPacket(const QuicPacketHeader & revived_header,base::StringPiece payload)620 void QuicConnectionLogger::OnRevivedPacket(
621 const QuicPacketHeader& revived_header,
622 base::StringPiece payload) {
623 net_log_.AddEvent(
624 NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_REVIVED,
625 base::Bind(&NetLogQuicPacketHeaderCallback, &revived_header));
626 }
627
OnCryptoHandshakeMessageReceived(const CryptoHandshakeMessage & message)628 void QuicConnectionLogger::OnCryptoHandshakeMessageReceived(
629 const CryptoHandshakeMessage& message) {
630 net_log_.AddEvent(
631 NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_RECEIVED,
632 base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
633
634 if (message.tag() == kSHLO) {
635 StringPiece address;
636 QuicSocketAddressCoder decoder;
637 if (message.GetStringPiece(kCADR, &address) &&
638 decoder.Decode(address.data(), address.size())) {
639 local_address_from_shlo_ = IPEndPoint(decoder.ip(), decoder.port());
640 UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.ConnectionTypeFromPeer",
641 GetRealAddressFamily(
642 local_address_from_shlo_.address()),
643 ADDRESS_FAMILY_LAST);
644 }
645 }
646 }
647
OnCryptoHandshakeMessageSent(const CryptoHandshakeMessage & message)648 void QuicConnectionLogger::OnCryptoHandshakeMessageSent(
649 const CryptoHandshakeMessage& message) {
650 net_log_.AddEvent(
651 NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_SENT,
652 base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
653 }
654
OnConnectionClosed(QuicErrorCode error,bool from_peer)655 void QuicConnectionLogger::OnConnectionClosed(QuicErrorCode error,
656 bool from_peer) {
657 net_log_.AddEvent(
658 NetLog::TYPE_QUIC_SESSION_CLOSED,
659 base::Bind(&NetLogQuicOnConnectionClosedCallback, error, from_peer));
660 }
661
OnSuccessfulVersionNegotiation(const QuicVersion & version)662 void QuicConnectionLogger::OnSuccessfulVersionNegotiation(
663 const QuicVersion& version) {
664 string quic_version = QuicVersionToString(version);
665 net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATED,
666 NetLog::StringCallback("version", &quic_version));
667 }
668
UpdateReceivedFrameCounts(QuicStreamId stream_id,int num_frames_received,int num_duplicate_frames_received)669 void QuicConnectionLogger::UpdateReceivedFrameCounts(
670 QuicStreamId stream_id,
671 int num_frames_received,
672 int num_duplicate_frames_received) {
673 if (stream_id != kCryptoStreamId) {
674 num_frames_received_ += num_frames_received;
675 num_duplicate_frames_received_ += num_duplicate_frames_received;
676 }
677 }
678
GetPacketSequenceNumberHistogram(const char * statistic_name) const679 base::HistogramBase* QuicConnectionLogger::GetPacketSequenceNumberHistogram(
680 const char* statistic_name) const {
681 string prefix("Net.QuicSession.PacketReceived_");
682 return base::LinearHistogram::FactoryGet(
683 prefix + statistic_name + connection_description_,
684 1, received_packets_.size(), received_packets_.size() + 1,
685 base::HistogramBase::kUmaTargetedHistogramFlag);
686 }
687
Get6PacketHistogram(const char * which_6) const688 base::HistogramBase* QuicConnectionLogger::Get6PacketHistogram(
689 const char* which_6) const {
690 // This histogram takes a binary encoding of the 6 consecutive packets
691 // received. As a result, there are 64 possible sample-patterns.
692 string prefix("Net.QuicSession.6PacketsPatternsReceived_");
693 return base::LinearHistogram::FactoryGet(
694 prefix + which_6 + connection_description_, 1, 64, 65,
695 base::HistogramBase::kUmaTargetedHistogramFlag);
696 }
697
Get21CumulativeHistogram(const char * which_21) const698 base::HistogramBase* QuicConnectionLogger::Get21CumulativeHistogram(
699 const char* which_21) const {
700 // This histogram contains, for each sequence of 21 packets, the results from
701 // 21 distinct questions about that sequence. Conceptually the histogtram is
702 // broken into 21 distinct ranges, and one sample is added into each of those
703 // ranges whenever we process a set of 21 packets.
704 // There is a little rendundancy, as each "range" must have the same number
705 // of samples, all told, but the histogram is a tad easier to read this way.
706 // The questions are:
707 // Was the first packet present (bucket 0==>no; bucket 1==>yes)
708 // Of the first two packets, how many were present? (bucket 2==> none;
709 // bucket 3==> 1 of 2; bucket 4==> 2 of 2)
710 // Of the first three packets, how many were present? (bucket 5==>none;
711 // bucket 6==> 1 of 3; bucket 7==> 2 of 3; bucket 8==> 3 of 3).
712 // etc.
713 string prefix("Net.QuicSession.21CumulativePacketsReceived_");
714 return base::LinearHistogram::FactoryGet(
715 prefix + which_21 + connection_description_,
716 1, kBoundingSampleInCumulativeHistogram,
717 kBoundingSampleInCumulativeHistogram + 1,
718 base::HistogramBase::kUmaTargetedHistogramFlag);
719 }
720
721 // static
AddTo21CumulativeHistogram(base::HistogramBase * histogram,int bit_mask_of_packets,int valid_bits_in_mask)722 void QuicConnectionLogger::AddTo21CumulativeHistogram(
723 base::HistogramBase* histogram,
724 int bit_mask_of_packets,
725 int valid_bits_in_mask) {
726 DCHECK_LE(valid_bits_in_mask, 21);
727 DCHECK_LT(bit_mask_of_packets, 1 << 21);
728 const int blank_bits_in_mask = 21 - valid_bits_in_mask;
729 DCHECK_EQ(bit_mask_of_packets & ((1 << blank_bits_in_mask) - 1), 0);
730 bit_mask_of_packets >>= blank_bits_in_mask;
731 int bits_so_far = 0;
732 int range_start = 0;
733 for (int i = 1; i <= valid_bits_in_mask; ++i) {
734 bits_so_far += bit_mask_of_packets & 1;
735 bit_mask_of_packets >>= 1;
736 DCHECK_LT(range_start + bits_so_far, kBoundingSampleInCumulativeHistogram);
737 histogram->Add(range_start + bits_so_far);
738 range_start += i + 1;
739 }
740 }
741
RecordAggregatePacketLossRate() const742 void QuicConnectionLogger::RecordAggregatePacketLossRate() const {
743 // For short connections under 22 packets in length, we'll rely on the
744 // Net.QuicSession.21CumulativePacketsReceived_* histogram to indicate packet
745 // loss rates. This way we avoid tremendously anomalous contributions to our
746 // histogram. (e.g., if we only got 5 packets, but lost 1, we'd otherwise
747 // record a 20% loss in this histogram!). We may still get some strange data
748 // (1 loss in 22 is still high :-/).
749 if (largest_received_packet_sequence_number_ <= 21)
750 return;
751
752 QuicPacketSequenceNumber divisor = largest_received_packet_sequence_number_;
753 QuicPacketSequenceNumber numerator = divisor - num_packets_received_;
754 if (divisor < 100000)
755 numerator *= 1000;
756 else
757 divisor /= 1000;
758 string prefix("Net.QuicSession.PacketLossRate_");
759 base::HistogramBase* histogram = base::Histogram::FactoryGet(
760 prefix + connection_description_, 1, 1000, 75,
761 base::HistogramBase::kUmaTargetedHistogramFlag);
762 histogram->Add(numerator / divisor);
763 }
764
RecordLossHistograms() const765 void QuicConnectionLogger::RecordLossHistograms() const {
766 if (largest_received_packet_sequence_number_ == 0)
767 return; // Connection was never used.
768 RecordAggregatePacketLossRate();
769
770 base::HistogramBase* is_not_ack_histogram =
771 GetPacketSequenceNumberHistogram("IsNotAck_");
772 base::HistogramBase* is_an_ack_histogram =
773 GetPacketSequenceNumberHistogram("IsAnAck_");
774 base::HistogramBase* packet_arrived_histogram =
775 GetPacketSequenceNumberHistogram("Ack_");
776 base::HistogramBase* packet_missing_histogram =
777 GetPacketSequenceNumberHistogram("Nack_");
778 base::HistogramBase* ongoing_cumulative_packet_histogram =
779 Get21CumulativeHistogram("Some21s_");
780 base::HistogramBase* first_cumulative_packet_histogram =
781 Get21CumulativeHistogram("First21_");
782 base::HistogramBase* six_packet_histogram = Get6PacketHistogram("Some6s_");
783
784 DCHECK_EQ(received_packets_.size(), received_acks_.size());
785 const QuicPacketSequenceNumber last_index =
786 std::min<QuicPacketSequenceNumber>(received_packets_.size() - 1,
787 largest_received_packet_sequence_number_);
788 const QuicPacketSequenceNumber index_of_first_21_contribution =
789 std::min<QuicPacketSequenceNumber>(21, last_index);
790 // Bit pattern of consecutively received packets that is maintained as we scan
791 // through the received_packets_ vector. Less significant bits correspond to
792 // less recent packets, and only the low order 21 bits are ever defined.
793 // Bit is 1 iff corresponding packet was received.
794 int packet_pattern_21 = 0;
795 // Zero is an invalid packet sequence number.
796 DCHECK(!received_packets_[0]);
797 for (size_t i = 1; i <= last_index; ++i) {
798 if (received_acks_[i])
799 is_an_ack_histogram->Add(i);
800 else
801 is_not_ack_histogram->Add(i);
802
803 packet_pattern_21 >>= 1;
804 if (received_packets_[i]) {
805 packet_arrived_histogram->Add(i);
806 packet_pattern_21 |= (1 << 20); // Turn on the 21st bit.
807 } else {
808 packet_missing_histogram->Add(i);
809 }
810
811 if (i == index_of_first_21_contribution) {
812 AddTo21CumulativeHistogram(first_cumulative_packet_histogram,
813 packet_pattern_21, i);
814 }
815 // We'll just record for non-overlapping ranges, to reduce histogramming
816 // cost for now. Each call does 21 separate histogram additions.
817 if (i > 21 || i % 21 == 0) {
818 AddTo21CumulativeHistogram(ongoing_cumulative_packet_histogram,
819 packet_pattern_21, 21);
820 }
821
822 if (i < 6)
823 continue; // Not enough packets to do any pattern recording.
824 int recent_6_mask = packet_pattern_21 >> 15;
825 DCHECK_LT(recent_6_mask, 64);
826 if (i == 6) {
827 Get6PacketHistogram("First6_")->Add(recent_6_mask);
828 continue;
829 }
830 // Record some overlapping patterns, to get a better picture, since this is
831 // not very expensive.
832 if (i % 3 == 0)
833 six_packet_histogram->Add(recent_6_mask);
834 }
835 }
836
837 } // namespace net
838