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
NetLogQuicPacketCallback(const IPEndPoint * self_address,const IPEndPoint * peer_address,size_t packet_size,NetLog::LogLevel)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
NetLogQuicPacketSentCallback(QuicPacketSequenceNumber sequence_number,EncryptionLevel level,TransmissionType transmission_type,size_t packet_size,WriteResult result,NetLog::LogLevel)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
NetLogQuicPacketRetransmittedCallback(QuicPacketSequenceNumber old_sequence_number,QuicPacketSequenceNumber new_sequence_number,NetLog::LogLevel)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
NetLogQuicPacketHeaderCallback(const QuicPacketHeader * header,NetLog::LogLevel)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
NetLogQuicStreamFrameCallback(const QuicStreamFrame * frame,NetLog::LogLevel)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
NetLogQuicAckFrameCallback(const QuicAckFrame * frame,NetLog::LogLevel)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
NetLogQuicCongestionFeedbackFrameCallback(const QuicCongestionFeedbackFrame * frame,NetLog::LogLevel)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
NetLogQuicRstStreamFrameCallback(const QuicRstStreamFrame * frame,NetLog::LogLevel)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
NetLogQuicConnectionCloseFrameCallback(const QuicConnectionCloseFrame * frame,NetLog::LogLevel)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
NetLogQuicWindowUpdateFrameCallback(const QuicWindowUpdateFrame * frame,NetLog::LogLevel)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
NetLogQuicBlockedFrameCallback(const QuicBlockedFrame * frame,NetLog::LogLevel)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
NetLogQuicGoAwayFrameCallback(const QuicGoAwayFrame * frame,NetLog::LogLevel)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
NetLogQuicStopWaitingFrameCallback(const QuicStopWaitingFrame * frame,NetLog::LogLevel)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
NetLogQuicVersionNegotiationPacketCallback(const QuicVersionNegotiationPacket * packet,NetLog::LogLevel)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
NetLogQuicCryptoHandshakeMessageCallback(const CryptoHandshakeMessage * message,NetLog::LogLevel)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
NetLogQuicOnConnectionClosedCallback(QuicErrorCode error,bool from_peer,NetLog::LogLevel)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
NetLogQuicCertificateVerifiedCallback(scoped_refptr<X509Certificate> cert,NetLog::LogLevel)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
UpdatePacketGapSentHistogram(size_t num_consecutive_missing_packets)264 void UpdatePacketGapSentHistogram(size_t num_consecutive_missing_packets) {
265 UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapSent",
266 num_consecutive_missing_packets);
267 }
268
UpdatePublicResetAddressMismatchHistogram(const IPEndPoint & server_hello_address,const IPEndPoint & public_reset_address)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
GetConnectionDescriptionString()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().
GetRealAddressFamily(const IPAddressNumber & address)329 AddressFamily GetRealAddressFamily(const IPAddressNumber& address) {
330 return IsIPv4Mapped(address) ? ADDRESS_FAMILY_IPV4 :
331 GetAddressFamily(address);
332 }
333
334 } // namespace
335
QuicConnectionLogger(const BoundNetLog & net_log)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
~QuicConnectionLogger()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
OnFrameAddedToPacket(const QuicFrame & frame)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
OnPacketSent(QuicPacketSequenceNumber sequence_number,EncryptionLevel level,TransmissionType transmission_type,const QuicEncryptedPacket & packet,WriteResult result)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
OnPacketRetransmitted(QuicPacketSequenceNumber old_sequence_number,QuicPacketSequenceNumber new_sequence_number)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
OnPacketReceived(const IPEndPoint & self_address,const IPEndPoint & peer_address,const QuicEncryptedPacket & packet)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
OnIncorrectConnectionId(QuicConnectionId connection_id)512 void QuicConnectionLogger::OnIncorrectConnectionId(
513 QuicConnectionId connection_id) {
514 ++num_incorrect_connection_ids_;
515 }
516
OnUndecryptablePacket()517 void QuicConnectionLogger::OnUndecryptablePacket() {
518 ++num_undecryptable_packets_;
519 }
520
OnDuplicatePacket(QuicPacketSequenceNumber sequence_number)521 void QuicConnectionLogger::OnDuplicatePacket(
522 QuicPacketSequenceNumber sequence_number) {
523 ++num_duplicate_packets_;
524 }
525
OnProtocolVersionMismatch(QuicVersion received_version)526 void QuicConnectionLogger::OnProtocolVersionMismatch(
527 QuicVersion received_version) {
528 // TODO(rtenneti): Add logging.
529 }
530
OnPacketHeader(const QuicPacketHeader & header)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
OnStreamFrame(const QuicStreamFrame & frame)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
OnAckFrame(const QuicAckFrame & frame)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
OnCongestionFeedbackFrame(const QuicCongestionFeedbackFrame & frame)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
OnStopWaitingFrame(const QuicStopWaitingFrame & frame)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
OnRstStreamFrame(const QuicRstStreamFrame & frame)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
OnConnectionCloseFrame(const QuicConnectionCloseFrame & frame)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
OnWindowUpdateFrame(const QuicWindowUpdateFrame & frame)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
OnBlockedFrame(const QuicBlockedFrame & frame)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
OnGoAwayFrame(const QuicGoAwayFrame & frame)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
OnPingFrame(const QuicPingFrame & frame)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
OnPublicResetPacket(const QuicPublicResetPacket & packet)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
OnVersionNegotiationPacket(const QuicVersionNegotiationPacket & packet)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
OnRevivedPacket(const QuicPacketHeader & revived_header,base::StringPiece payload)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
OnCryptoHandshakeMessageReceived(const CryptoHandshakeMessage & message)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
OnCryptoHandshakeMessageSent(const CryptoHandshakeMessage & message)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
OnConnectionClosed(QuicErrorCode error,bool from_peer)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
OnSuccessfulVersionNegotiation(const QuicVersion & version)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
UpdateReceivedFrameCounts(QuicStreamId stream_id,int num_frames_received,int num_duplicate_frames_received)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
OnCertificateVerified(const CertVerifyResult & result)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
GetPacketSequenceNumberHistogram(const char * statistic_name) const747 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
Get6PacketHistogram(const char * which_6) const756 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
Get21CumulativeHistogram(const char * which_21) const766 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
AddTo21CumulativeHistogram(base::HistogramBase * histogram,int bit_mask_of_packets,int valid_bits_in_mask)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
RecordAggregatePacketLossRate() const810 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
RecordLossHistograms() const833 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