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
25using base::StringPiece;
26using std::string;
27
28namespace net {
29
30namespace {
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.
35const int kBoundingSampleInCumulativeHistogram = ((2 + 22) * 21) / 2;
36
37base::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
48base::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
67base::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
79base::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
94base::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
104base::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
145base::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
159base::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
169base::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
178base::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
187base::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
195base::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
205base::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
216base::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
229base::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
237base::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
247base::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
264void UpdatePacketGapSentHistogram(size_t num_consecutive_missing_packets) {
265  UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapSent",
266                       num_consecutive_missing_packets);
267}
268
269void 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
282const 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().
329AddressFamily GetRealAddressFamily(const IPAddressNumber& address) {
330  return IsIPv4Mapped(address) ? ADDRESS_FAMILY_IPV4 :
331      GetAddressFamily(address);
332}
333
334}  // namespace
335
336QuicConnectionLogger::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
354QuicConnectionLogger::~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
386void 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
474void 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
486void 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
495void 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
512void QuicConnectionLogger::OnIncorrectConnectionId(
513    QuicConnectionId connection_id) {
514  ++num_incorrect_connection_ids_;
515}
516
517void QuicConnectionLogger::OnUndecryptablePacket() {
518  ++num_undecryptable_packets_;
519}
520
521void QuicConnectionLogger::OnDuplicatePacket(
522    QuicPacketSequenceNumber sequence_number) {
523  ++num_duplicate_packets_;
524}
525
526void QuicConnectionLogger::OnProtocolVersionMismatch(
527    QuicVersion received_version) {
528  // TODO(rtenneti): Add logging.
529}
530
531void 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
559void QuicConnectionLogger::OnStreamFrame(const QuicStreamFrame& frame) {
560  net_log_.AddEvent(
561      NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_RECEIVED,
562      base::Bind(&NetLogQuicStreamFrameCallback, &frame));
563}
564
565void 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
614void 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
621void 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
628void 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
636void 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
643void 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
650void QuicConnectionLogger::OnBlockedFrame(const QuicBlockedFrame& frame) {
651  net_log_.AddEvent(
652      NetLog::TYPE_QUIC_SESSION_BLOCKED_FRAME_RECEIVED,
653      base::Bind(&NetLogQuicBlockedFrameCallback, &frame));
654}
655
656void QuicConnectionLogger::OnGoAwayFrame(const QuicGoAwayFrame& frame) {
657  net_log_.AddEvent(
658      NetLog::TYPE_QUIC_SESSION_GOAWAY_FRAME_RECEIVED,
659      base::Bind(&NetLogQuicGoAwayFrameCallback, &frame));
660}
661
662void 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
667void 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
674void 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
681void 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
689void 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
709void 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
716void 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
723void 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
730void 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
740void 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
747base::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
756base::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
766base::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
790void 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
810void 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
833void 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