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 <limits>
9 #include <memory>
10 #include <utility>
11 #include <vector>
12
13 #include "base/metrics/histogram_base.h"
14 #include "base/metrics/histogram_functions.h"
15 #include "base/metrics/histogram_macros.h"
16 #include "base/values.h"
17 #include "net/base/ip_address.h"
18 #include "net/cert/x509_certificate.h"
19 #include "net/log/net_log_capture_mode.h"
20 #include "net/log/net_log_event_type.h"
21 #include "net/log/net_log_values.h"
22 #include "net/quic/address_utils.h"
23 #include "net/quic/quic_address_mismatch.h"
24 #include "net/third_party/quiche/src/common/platform/api/quiche_string_piece.h"
25 #include "net/third_party/quiche/src/quic/core/crypto/crypto_handshake_message.h"
26 #include "net/third_party/quiche/src/quic/core/crypto/crypto_protocol.h"
27 #include "net/third_party/quiche/src/quic/core/quic_connection_id.h"
28 #include "net/third_party/quiche/src/quic/core/quic_packets.h"
29 #include "net/third_party/quiche/src/quic/core/quic_socket_address_coder.h"
30 #include "net/third_party/quiche/src/quic/core/quic_time.h"
31 #include "net/third_party/quiche/src/quic/core/quic_utils.h"
32
33 using quic::kMaxOutgoingPacketSize;
34 using std::string;
35
36 namespace net {
37
38 namespace {
39
NetLogQuicPacketParams(const quic::QuicSocketAddress & self_address,const quic::QuicSocketAddress & peer_address,size_t packet_size)40 base::Value NetLogQuicPacketParams(const quic::QuicSocketAddress& self_address,
41 const quic::QuicSocketAddress& peer_address,
42 size_t packet_size) {
43 base::Value dict(base::Value::Type::DICTIONARY);
44 dict.SetStringKey("self_address", self_address.ToString());
45 dict.SetStringKey("peer_address", peer_address.ToString());
46 dict.SetIntKey("size", packet_size);
47 return dict;
48 }
49
NetLogQuicPacketSentParams(const quic::SerializedPacket & serialized_packet,quic::TransmissionType transmission_type,quic::QuicTime sent_time)50 base::Value NetLogQuicPacketSentParams(
51 const quic::SerializedPacket& serialized_packet,
52 quic::TransmissionType transmission_type,
53 quic::QuicTime sent_time) {
54 base::Value dict(base::Value::Type::DICTIONARY);
55 dict.SetStringKey("transmission_type",
56 quic::TransmissionTypeToString(transmission_type));
57 dict.SetKey("packet_number",
58 NetLogNumberValue(serialized_packet.packet_number.ToUint64()));
59 dict.SetIntKey("size", serialized_packet.encrypted_length);
60 dict.SetKey("sent_time_us", NetLogNumberValue(sent_time.ToDebuggingValue()));
61 dict.SetStringKey(
62 "encryption_level",
63 quic::EncryptionLevelToString(serialized_packet.encryption_level));
64 return dict;
65 }
66
NetLogQuicPacketLostParams(quic::QuicPacketNumber packet_number,quic::TransmissionType transmission_type,quic::QuicTime detection_time)67 base::Value NetLogQuicPacketLostParams(quic::QuicPacketNumber packet_number,
68 quic::TransmissionType transmission_type,
69 quic::QuicTime detection_time) {
70 base::Value dict(base::Value::Type::DICTIONARY);
71 dict.SetStringKey("transmission_type",
72 quic::TransmissionTypeToString(transmission_type));
73 dict.SetKey("packet_number", NetLogNumberValue(packet_number.ToUint64()));
74 dict.SetKey("detection_time_us",
75 NetLogNumberValue(detection_time.ToDebuggingValue()));
76 return dict;
77 }
78
NetLogQuicDuplicatePacketParams(quic::QuicPacketNumber packet_number)79 base::Value NetLogQuicDuplicatePacketParams(
80 quic::QuicPacketNumber packet_number) {
81 base::Value dict(base::Value::Type::DICTIONARY);
82 dict.SetKey("packet_number", NetLogNumberValue(packet_number.ToUint64()));
83 return dict;
84 }
85
NetLogQuicPacketHeaderParams(const quic::QuicPacketHeader * header,bool is_ietf_quic)86 base::Value NetLogQuicPacketHeaderParams(const quic::QuicPacketHeader* header,
87 bool is_ietf_quic) {
88 base::Value dict(base::Value::Type::DICTIONARY);
89 dict.SetStringKey("connection_id",
90 header->destination_connection_id.ToString());
91 dict.SetKey("packet_number",
92 NetLogNumberValue(header->packet_number.ToUint64()));
93 dict.SetStringKey("header_format",
94 quic::PacketHeaderFormatToString(header->form));
95 if (header->form == quic::IETF_QUIC_LONG_HEADER_PACKET) {
96 dict.SetStringKey("long_header_type", quic::QuicLongHeaderTypeToString(
97 header->long_packet_type));
98 }
99 if (!is_ietf_quic) {
100 dict.SetIntKey("reset_flag", header->reset_flag);
101 dict.SetIntKey("version_flag", header->version_flag);
102 }
103 return dict;
104 }
105
NetLogQuicStreamFrameParams(const quic::QuicStreamFrame & frame)106 base::Value NetLogQuicStreamFrameParams(const quic::QuicStreamFrame& frame) {
107 base::Value dict(base::Value::Type::DICTIONARY);
108 dict.SetIntKey("stream_id", frame.stream_id);
109 dict.SetBoolKey("fin", frame.fin);
110 dict.SetKey("offset", NetLogNumberValue(frame.offset));
111 dict.SetIntKey("length", frame.data_length);
112 return dict;
113 }
114
NetLogQuicAckFrameParams(const quic::QuicAckFrame * frame)115 base::Value NetLogQuicAckFrameParams(const quic::QuicAckFrame* frame) {
116 base::Value dict(base::Value::Type::DICTIONARY);
117 dict.SetKey("largest_observed",
118 NetLogNumberValue(frame->largest_acked.ToUint64()));
119 dict.SetKey("delta_time_largest_observed_us",
120 NetLogNumberValue(frame->ack_delay_time.ToMicroseconds()));
121
122 base::Value missing(base::Value::Type::LIST);
123 if (!frame->packets.Empty()) {
124 // V34 and above express acked packets, but only print
125 // missing packets, because it's typically a shorter list.
126 for (quic::QuicPacketNumber packet = frame->packets.Min();
127 packet < frame->largest_acked; ++packet) {
128 if (!frame->packets.Contains(packet)) {
129 missing.Append(NetLogNumberValue(packet.ToUint64()));
130 }
131 }
132 }
133 dict.SetKey("missing_packets", std::move(missing));
134
135 base::Value received(base::Value::Type::LIST);
136 const quic::PacketTimeVector& received_times = frame->received_packet_times;
137 for (auto it = received_times.begin(); it != received_times.end(); ++it) {
138 base::Value info(base::Value::Type::DICTIONARY);
139 info.SetKey("packet_number", NetLogNumberValue(it->first.ToUint64()));
140 info.SetKey("received", NetLogNumberValue(it->second.ToDebuggingValue()));
141 received.Append(std::move(info));
142 }
143 dict.SetKey("received_packet_times", std::move(received));
144
145 return dict;
146 }
147
NetLogQuicRstStreamFrameParams(const quic::QuicRstStreamFrame * frame)148 base::Value NetLogQuicRstStreamFrameParams(
149 const quic::QuicRstStreamFrame* frame) {
150 base::Value dict(base::Value::Type::DICTIONARY);
151 dict.SetIntKey("stream_id", frame->stream_id);
152 dict.SetIntKey("quic_rst_stream_error", frame->error_code);
153 dict.SetKey("offset", NetLogNumberValue(frame->byte_offset));
154 return dict;
155 }
156
NetLogQuicConnectionCloseFrameParams(const quic::QuicConnectionCloseFrame * frame)157 base::Value NetLogQuicConnectionCloseFrameParams(
158 const quic::QuicConnectionCloseFrame* frame) {
159 base::Value dict(base::Value::Type::DICTIONARY);
160 dict.SetIntKey("quic_error", frame->quic_error_code);
161 dict.SetStringKey("details", frame->error_details);
162 return dict;
163 }
164
NetLogQuicWindowUpdateFrameParams(const quic::QuicWindowUpdateFrame * frame)165 base::Value NetLogQuicWindowUpdateFrameParams(
166 const quic::QuicWindowUpdateFrame* frame) {
167 base::Value dict(base::Value::Type::DICTIONARY);
168 dict.SetIntKey("stream_id", frame->stream_id);
169 dict.SetKey("byte_offset", NetLogNumberValue(frame->max_data));
170 return dict;
171 }
172
NetLogQuicBlockedFrameParams(const quic::QuicBlockedFrame * frame)173 base::Value NetLogQuicBlockedFrameParams(const quic::QuicBlockedFrame* frame) {
174 base::Value dict(base::Value::Type::DICTIONARY);
175 dict.SetIntKey("stream_id", frame->stream_id);
176 return dict;
177 }
178
NetLogQuicGoAwayFrameParams(const quic::QuicGoAwayFrame * frame)179 base::Value NetLogQuicGoAwayFrameParams(const quic::QuicGoAwayFrame* frame) {
180 base::Value dict(base::Value::Type::DICTIONARY);
181 dict.SetIntKey("quic_error", frame->error_code);
182 dict.SetIntKey("last_good_stream_id", frame->last_good_stream_id);
183 dict.SetStringKey("reason_phrase", frame->reason_phrase);
184 return dict;
185 }
186
NetLogQuicStopWaitingFrameParams(const quic::QuicStopWaitingFrame * frame)187 base::Value NetLogQuicStopWaitingFrameParams(
188 const quic::QuicStopWaitingFrame* frame) {
189 base::Value dict(base::Value::Type::DICTIONARY);
190 dict.SetKey("least_unacked",
191 NetLogNumberValue(frame->least_unacked.ToUint64()));
192 return dict;
193 }
194
NetLogQuicVersionNegotiationPacketParams(const quic::QuicVersionNegotiationPacket * packet)195 base::Value NetLogQuicVersionNegotiationPacketParams(
196 const quic::QuicVersionNegotiationPacket* packet) {
197 base::Value dict(base::Value::Type::DICTIONARY);
198 base::Value versions(base::Value::Type::LIST);
199 for (auto it = packet->versions.begin(); it != packet->versions.end(); ++it) {
200 versions.Append(ParsedQuicVersionToString(*it));
201 }
202 dict.SetKey("versions", std::move(versions));
203 return dict;
204 }
205
NetLogQuicPublicResetPacketParams(const IPEndPoint & server_hello_address,const quic::QuicSocketAddress & public_reset_address)206 base::Value NetLogQuicPublicResetPacketParams(
207 const IPEndPoint& server_hello_address,
208 const quic::QuicSocketAddress& public_reset_address) {
209 base::Value dict(base::Value::Type::DICTIONARY);
210 dict.SetStringKey("server_hello_address", server_hello_address.ToString());
211 dict.SetStringKey("public_reset_address", public_reset_address.ToString());
212 return dict;
213 }
214
NetLogQuicPathData(const quic::QuicPathFrameBuffer & buffer)215 base::Value NetLogQuicPathData(const quic::QuicPathFrameBuffer& buffer) {
216 base::Value dict(base::Value::Type::DICTIONARY);
217 dict.SetKey("data",
218 NetLogBinaryValue(reinterpret_cast<const char*>(buffer.data()),
219 buffer.size()));
220 return dict;
221 }
222
NetLogQuicCryptoHandshakeMessageParams(const quic::CryptoHandshakeMessage * message)223 base::Value NetLogQuicCryptoHandshakeMessageParams(
224 const quic::CryptoHandshakeMessage* message) {
225 base::Value dict(base::Value::Type::DICTIONARY);
226 dict.SetStringKey("quic_crypto_handshake_message", message->DebugString());
227 return dict;
228 }
229
NetLogQuicOnConnectionClosedParams(quic::QuicErrorCode error,string error_details,quic::ConnectionCloseSource source)230 base::Value NetLogQuicOnConnectionClosedParams(
231 quic::QuicErrorCode error,
232 string error_details,
233 quic::ConnectionCloseSource source) {
234 base::Value dict(base::Value::Type::DICTIONARY);
235 dict.SetIntKey("quic_error", error);
236 dict.SetStringKey("details", error_details);
237 dict.SetBoolKey("from_peer", source == quic::ConnectionCloseSource::FROM_PEER
238 ? true
239 : false);
240 return dict;
241 }
242
NetLogQuicCertificateVerifiedParams(scoped_refptr<X509Certificate> cert)243 base::Value NetLogQuicCertificateVerifiedParams(
244 scoped_refptr<X509Certificate> cert) {
245 // Only the subjects are logged so that we can investigate connection pooling.
246 // More fields could be logged in the future.
247 std::vector<std::string> dns_names;
248 cert->GetSubjectAltName(&dns_names, nullptr);
249 base::Value dict(base::Value::Type::DICTIONARY);
250 base::Value subjects(base::Value::Type::LIST);
251 for (auto& dns_name : dns_names) {
252 subjects.Append(std::move(dns_name));
253 }
254 dict.SetKey("subjects", std::move(subjects));
255 return dict;
256 }
257
NetLogQuicCryptoFrameParams(const quic::QuicCryptoFrame * frame,bool has_buffer)258 base::Value NetLogQuicCryptoFrameParams(const quic::QuicCryptoFrame* frame,
259 bool has_buffer) {
260 base::Value dict(base::Value::Type::DICTIONARY);
261 dict.SetStringKey("encryption_level",
262 quic::EncryptionLevelToString(frame->level));
263 dict.SetIntKey("data_length", frame->data_length);
264 dict.SetKey("offset", NetLogNumberValue(frame->offset));
265 if (has_buffer) {
266 dict.SetKey("bytes", NetLogBinaryValue(
267 reinterpret_cast<const void*>(frame->data_buffer),
268 frame->data_length));
269 }
270 return dict;
271 }
272
NetLogQuicStopSendingFrameParams(const quic::QuicStopSendingFrame * frame)273 base::Value NetLogQuicStopSendingFrameParams(
274 const quic::QuicStopSendingFrame* frame) {
275 base::Value dict(base::Value::Type::DICTIONARY);
276 dict.SetIntKey("stream_id", frame->stream_id);
277 dict.SetIntKey("application_error_code", frame->application_error_code);
278 return dict;
279 }
280
NetLogQuicStreamsBlockedFrameParams(const quic::QuicStreamsBlockedFrame & frame)281 base::Value NetLogQuicStreamsBlockedFrameParams(
282 const quic::QuicStreamsBlockedFrame& frame) {
283 base::Value dict(base::Value::Type::DICTIONARY);
284 dict.SetIntKey("stream_count", frame.stream_count);
285 dict.SetBoolKey("is_unidirectional", frame.unidirectional);
286 return dict;
287 }
288
NetLogQuicMaxStreamsFrameParams(const quic::QuicMaxStreamsFrame & frame)289 base::Value NetLogQuicMaxStreamsFrameParams(
290 const quic::QuicMaxStreamsFrame& frame) {
291 base::Value dict(base::Value::Type::DICTIONARY);
292 dict.SetIntKey("stream_count", frame.stream_count);
293 dict.SetBoolKey("is_unidirectional", frame.unidirectional);
294 return dict;
295 }
296
NetLogQuicNewConnectionIdFrameParams(const quic::QuicNewConnectionIdFrame * frame)297 base::Value NetLogQuicNewConnectionIdFrameParams(
298 const quic::QuicNewConnectionIdFrame* frame) {
299 base::Value dict(base::Value::Type::DICTIONARY);
300 dict.SetStringKey("connection_id", frame->connection_id.ToString());
301 dict.SetKey("sequence_number", NetLogNumberValue(frame->sequence_number));
302 dict.SetKey("retire_prior_to", NetLogNumberValue(frame->retire_prior_to));
303 return dict;
304 }
305
NetLogQuicRetireConnectionIdFrameParams(const quic::QuicRetireConnectionIdFrame * frame)306 base::Value NetLogQuicRetireConnectionIdFrameParams(
307 const quic::QuicRetireConnectionIdFrame* frame) {
308 base::Value dict(base::Value::Type::DICTIONARY);
309 dict.SetKey("sequence_number", NetLogNumberValue(frame->sequence_number));
310 return dict;
311 }
312
NetLogQuicNewTokenFrameParams(const quic::QuicNewTokenFrame * frame)313 base::Value NetLogQuicNewTokenFrameParams(
314 const quic::QuicNewTokenFrame* frame) {
315 base::Value dict(base::Value::Type::DICTIONARY);
316 dict.SetKey("token", NetLogBinaryValue(
317 reinterpret_cast<const void*>(frame->token.data()),
318 frame->token.length()));
319 return dict;
320 }
321
UpdatePublicResetAddressMismatchHistogram(const IPEndPoint & server_hello_address,const IPEndPoint & public_reset_address)322 void UpdatePublicResetAddressMismatchHistogram(
323 const IPEndPoint& server_hello_address,
324 const IPEndPoint& public_reset_address) {
325 int sample = GetAddressMismatch(server_hello_address, public_reset_address);
326 // We are seemingly talking to an older server that does not support the
327 // feature, so we can't report the results in the histogram.
328 if (sample < 0) {
329 return;
330 }
331 UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.PublicResetAddressMismatch2",
332 static_cast<QuicAddressMismatch>(sample),
333 QUIC_ADDRESS_MISMATCH_MAX);
334 }
335
336 // If |address| is an IPv4-mapped IPv6 address, returns ADDRESS_FAMILY_IPV4
337 // instead of ADDRESS_FAMILY_IPV6. Othewise, behaves like GetAddressFamily().
GetRealAddressFamily(const IPAddress & address)338 AddressFamily GetRealAddressFamily(const IPAddress& address) {
339 return address.IsIPv4MappedIPv6() ? ADDRESS_FAMILY_IPV4
340 : GetAddressFamily(address);
341 }
342
343 } // namespace
344
QuicConnectionLogger(quic::QuicSpdySession * session,const char * const connection_description,std::unique_ptr<SocketPerformanceWatcher> socket_performance_watcher,const NetLogWithSource & net_log)345 QuicConnectionLogger::QuicConnectionLogger(
346 quic::QuicSpdySession* session,
347 const char* const connection_description,
348 std::unique_ptr<SocketPerformanceWatcher> socket_performance_watcher,
349 const NetLogWithSource& net_log)
350 : net_log_(net_log),
351 session_(session),
352 last_received_packet_size_(0),
353 no_packet_received_after_ping_(false),
354 previous_received_packet_size_(0),
355 num_out_of_order_received_packets_(0),
356 num_out_of_order_large_received_packets_(0),
357 num_packets_received_(0),
358 num_frames_received_(0),
359 num_duplicate_frames_received_(0),
360 num_incorrect_connection_ids_(0),
361 num_undecryptable_packets_(0),
362 num_duplicate_packets_(0),
363 num_blocked_frames_received_(0),
364 num_blocked_frames_sent_(0),
365 connection_description_(connection_description),
366 socket_performance_watcher_(std::move(socket_performance_watcher)) {}
367
~QuicConnectionLogger()368 QuicConnectionLogger::~QuicConnectionLogger() {
369 UMA_HISTOGRAM_COUNTS_1M("Net.QuicSession.OutOfOrderPacketsReceived",
370 num_out_of_order_received_packets_);
371 UMA_HISTOGRAM_COUNTS_1M("Net.QuicSession.OutOfOrderLargePacketsReceived",
372 num_out_of_order_large_received_packets_);
373 UMA_HISTOGRAM_COUNTS_1M("Net.QuicSession.IncorrectConnectionIDsReceived",
374 num_incorrect_connection_ids_);
375 UMA_HISTOGRAM_COUNTS_1M("Net.QuicSession.UndecryptablePacketsReceived",
376 num_undecryptable_packets_);
377 UMA_HISTOGRAM_COUNTS_1M("Net.QuicSession.DuplicatePacketsReceived",
378 num_duplicate_packets_);
379 UMA_HISTOGRAM_COUNTS_1M("Net.QuicSession.BlockedFrames.Received",
380 num_blocked_frames_received_);
381 UMA_HISTOGRAM_COUNTS_1M("Net.QuicSession.BlockedFrames.Sent",
382 num_blocked_frames_sent_);
383
384 const quic::QuicConnectionStats& stats = session_->connection()->GetStats();
385 UMA_HISTOGRAM_TIMES("Net.QuicSession.MinRTT",
386 base::TimeDelta::FromMicroseconds(stats.min_rtt_us));
387 UMA_HISTOGRAM_TIMES("Net.QuicSession.SmoothedRTT",
388 base::TimeDelta::FromMicroseconds(stats.srtt_us));
389
390 if (num_frames_received_ > 0) {
391 int duplicate_stream_frame_per_thousand =
392 num_duplicate_frames_received_ * 1000 / num_frames_received_;
393 if (num_packets_received_ < 100) {
394 UMA_HISTOGRAM_CUSTOM_COUNTS(
395 "Net.QuicSession.StreamFrameDuplicatedShortConnection",
396 duplicate_stream_frame_per_thousand, 1, 1000, 75);
397 } else {
398 UMA_HISTOGRAM_CUSTOM_COUNTS(
399 "Net.QuicSession.StreamFrameDuplicatedLongConnection",
400 duplicate_stream_frame_per_thousand, 1, 1000, 75);
401 }
402 }
403
404 RecordAggregatePacketLossRate();
405 }
406
OnFrameAddedToPacket(const quic::QuicFrame & frame)407 void QuicConnectionLogger::OnFrameAddedToPacket(const quic::QuicFrame& frame) {
408 switch (frame.type) {
409 case quic::PADDING_FRAME:
410 break;
411 case quic::STREAM_FRAME:
412 break;
413 case quic::ACK_FRAME: {
414 break;
415 }
416 case quic::RST_STREAM_FRAME:
417 base::UmaHistogramSparse("Net.QuicSession.RstStreamErrorCodeClient",
418 frame.rst_stream_frame->error_code);
419 break;
420 case quic::CONNECTION_CLOSE_FRAME:
421 break;
422 case quic::GOAWAY_FRAME:
423 break;
424 case quic::WINDOW_UPDATE_FRAME:
425 break;
426 case quic::BLOCKED_FRAME:
427 ++num_blocked_frames_sent_;
428 break;
429 case quic::STOP_WAITING_FRAME:
430 break;
431 case quic::PING_FRAME:
432 UMA_HISTOGRAM_BOOLEAN("Net.QuicSession.ConnectionFlowControlBlocked",
433 session_->IsConnectionFlowControlBlocked());
434 UMA_HISTOGRAM_BOOLEAN("Net.QuicSession.StreamFlowControlBlocked",
435 session_->IsStreamFlowControlBlocked());
436 break;
437 case quic::MTU_DISCOVERY_FRAME:
438 break;
439 case quic::NEW_CONNECTION_ID_FRAME:
440 break;
441 case quic::MAX_STREAMS_FRAME:
442 break;
443 case quic::STREAMS_BLOCKED_FRAME:
444 break;
445 case quic::PATH_RESPONSE_FRAME:
446 break;
447 case quic::PATH_CHALLENGE_FRAME:
448 break;
449 case quic::STOP_SENDING_FRAME:
450 break;
451 case quic::MESSAGE_FRAME:
452 break;
453 case quic::CRYPTO_FRAME:
454 break;
455 case quic::NEW_TOKEN_FRAME:
456 break;
457 case quic::RETIRE_CONNECTION_ID_FRAME:
458 break;
459 default:
460 DCHECK(false) << "Illegal frame type: " << frame.type;
461 }
462 if (!net_log_.IsCapturing())
463 return;
464 switch (frame.type) {
465 case quic::PADDING_FRAME:
466 net_log_.AddEventWithIntParams(
467 NetLogEventType::QUIC_SESSION_PADDING_FRAME_SENT, "num_padding_bytes",
468 frame.padding_frame.num_padding_bytes);
469 break;
470 case quic::STREAM_FRAME:
471 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_STREAM_FRAME_SENT, [&] {
472 return NetLogQuicStreamFrameParams(frame.stream_frame);
473 });
474 break;
475 case quic::ACK_FRAME: {
476 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_ACK_FRAME_SENT, [&] {
477 return NetLogQuicAckFrameParams(frame.ack_frame);
478 });
479 break;
480 }
481 case quic::RST_STREAM_FRAME:
482 base::UmaHistogramSparse("Net.QuicSession.RstStreamErrorCodeClient",
483 frame.rst_stream_frame->error_code);
484 net_log_.AddEvent(
485 NetLogEventType::QUIC_SESSION_RST_STREAM_FRAME_SENT, [&] {
486 return NetLogQuicRstStreamFrameParams(frame.rst_stream_frame);
487 });
488 break;
489 case quic::CONNECTION_CLOSE_FRAME:
490 net_log_.AddEvent(
491 NetLogEventType::QUIC_SESSION_CONNECTION_CLOSE_FRAME_SENT, [&] {
492 return NetLogQuicConnectionCloseFrameParams(
493 frame.connection_close_frame);
494 });
495 break;
496 case quic::GOAWAY_FRAME:
497 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_GOAWAY_FRAME_SENT, [&] {
498 return NetLogQuicGoAwayFrameParams(frame.goaway_frame);
499 });
500 break;
501 case quic::WINDOW_UPDATE_FRAME:
502 net_log_.AddEvent(
503 NetLogEventType::QUIC_SESSION_WINDOW_UPDATE_FRAME_SENT, [&] {
504 return NetLogQuicWindowUpdateFrameParams(frame.window_update_frame);
505 });
506 break;
507 case quic::BLOCKED_FRAME:
508 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_BLOCKED_FRAME_SENT, [&] {
509 return NetLogQuicBlockedFrameParams(frame.blocked_frame);
510 });
511 break;
512 case quic::STOP_WAITING_FRAME:
513 net_log_.AddEvent(
514 NetLogEventType::QUIC_SESSION_STOP_WAITING_FRAME_SENT, [&] {
515 return NetLogQuicStopWaitingFrameParams(&frame.stop_waiting_frame);
516 });
517 break;
518 case quic::PING_FRAME:
519 UMA_HISTOGRAM_BOOLEAN("Net.QuicSession.ConnectionFlowControlBlocked",
520 session_->IsConnectionFlowControlBlocked());
521 UMA_HISTOGRAM_BOOLEAN("Net.QuicSession.StreamFlowControlBlocked",
522 session_->IsStreamFlowControlBlocked());
523 // PingFrame has no contents to log, so just record that it was sent.
524 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_PING_FRAME_SENT);
525 break;
526 case quic::MTU_DISCOVERY_FRAME:
527 // MtuDiscoveryFrame is PingFrame on wire, it does not have any payload.
528 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_MTU_DISCOVERY_FRAME_SENT);
529 break;
530 case quic::NEW_CONNECTION_ID_FRAME:
531 net_log_.AddEvent(
532 NetLogEventType::QUIC_SESSION_NEW_CONNECTION_ID_FRAME_SENT, [&] {
533 return NetLogQuicNewConnectionIdFrameParams(
534 frame.new_connection_id_frame);
535 });
536 break;
537 case quic::MAX_STREAMS_FRAME:
538 net_log_.AddEvent(
539 NetLogEventType::QUIC_SESSION_MAX_STREAMS_FRAME_SENT, [&] {
540 return NetLogQuicMaxStreamsFrameParams(frame.max_streams_frame);
541 });
542 break;
543 case quic::STREAMS_BLOCKED_FRAME:
544 net_log_.AddEvent(
545 NetLogEventType::QUIC_SESSION_STREAMS_BLOCKED_FRAME_SENT, [&] {
546 return NetLogQuicStreamsBlockedFrameParams(
547 frame.streams_blocked_frame);
548 });
549 break;
550 case quic::PATH_RESPONSE_FRAME:
551 net_log_.AddEvent(
552 NetLogEventType::QUIC_SESSION_PATH_RESPONSE_FRAME_SENT, [&] {
553 return NetLogQuicPathData(frame.path_response_frame->data_buffer);
554 });
555 break;
556 case quic::PATH_CHALLENGE_FRAME:
557 net_log_.AddEvent(
558 NetLogEventType::QUIC_SESSION_PATH_CHALLENGE_FRAME_SENT, [&] {
559 return NetLogQuicPathData(frame.path_challenge_frame->data_buffer);
560 });
561 break;
562 case quic::STOP_SENDING_FRAME:
563 net_log_.AddEvent(
564 NetLogEventType::QUIC_SESSION_STOP_SENDING_FRAME_SENT, [&] {
565 return NetLogQuicStopSendingFrameParams(frame.stop_sending_frame);
566 });
567 break;
568 case quic::MESSAGE_FRAME:
569 net_log_.AddEventWithIntParams(
570 NetLogEventType::QUIC_SESSION_MESSAGE_FRAME_SENT, "message_length",
571 frame.message_frame->message_length);
572 break;
573 case quic::CRYPTO_FRAME:
574 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_CRYPTO_FRAME_SENT, [&] {
575 return NetLogQuicCryptoFrameParams(frame.crypto_frame,
576 /*has_buffer = */ false);
577 });
578 break;
579 case quic::NEW_TOKEN_FRAME:
580 net_log_.AddEvent(
581 NetLogEventType::QUIC_SESSION_NEW_TOKEN_FRAME_SENT,
582 [&] { return NetLogQuicNewTokenFrameParams(frame.new_token_frame); });
583 break;
584 case quic::RETIRE_CONNECTION_ID_FRAME:
585 net_log_.AddEvent(
586 NetLogEventType::QUIC_SESSION_RETIRE_CONNECTION_ID_FRAME_SENT, [&] {
587 return NetLogQuicRetireConnectionIdFrameParams(
588 frame.retire_connection_id_frame);
589 });
590 break;
591 default:
592 DCHECK(false) << "Illegal frame type: " << frame.type;
593 }
594 }
595
OnStreamFrameCoalesced(const quic::QuicStreamFrame & frame)596 void QuicConnectionLogger::OnStreamFrameCoalesced(
597 const quic::QuicStreamFrame& frame) {
598 if (!net_log_.IsCapturing())
599 return;
600 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_STREAM_FRAME_COALESCED,
601 [&] { return NetLogQuicStreamFrameParams(frame); });
602 }
603
OnPacketSent(const quic::SerializedPacket & serialized_packet,quic::TransmissionType transmission_type,quic::QuicTime sent_time)604 void QuicConnectionLogger::OnPacketSent(
605 const quic::SerializedPacket& serialized_packet,
606 quic::TransmissionType transmission_type,
607 quic::QuicTime sent_time) {
608 // 4.4.1.4. Minimum Packet Size
609 // The payload of a UDP datagram carrying the Initial packet MUST be
610 // expanded to at least 1200 octets
611 const quic::QuicPacketLength kMinClientInitialPacketLength = 1200;
612 const quic::QuicPacketLength encrypted_length =
613 serialized_packet.encrypted_length;
614 switch (serialized_packet.encryption_level) {
615 case quic::ENCRYPTION_INITIAL:
616 UMA_HISTOGRAM_CUSTOM_COUNTS("Net.QuicSession.SendPacketSize.Initial",
617 encrypted_length, 1, kMaxOutgoingPacketSize,
618 50);
619 if (encrypted_length < kMinClientInitialPacketLength) {
620 UMA_HISTOGRAM_CUSTOM_COUNTS(
621 "Net.QuicSession.TooSmallInitialSentPacket",
622 kMinClientInitialPacketLength - encrypted_length, 1,
623 kMinClientInitialPacketLength, 50);
624 }
625 break;
626 case quic::ENCRYPTION_HANDSHAKE:
627 UMA_HISTOGRAM_CUSTOM_COUNTS("Net.QuicSession.SendPacketSize.Hanshake",
628 encrypted_length, 1, kMaxOutgoingPacketSize,
629 50);
630 break;
631 case quic::ENCRYPTION_ZERO_RTT:
632 UMA_HISTOGRAM_CUSTOM_COUNTS("Net.QuicSession.SendPacketSize.0RTT",
633 encrypted_length, 1, kMaxOutgoingPacketSize,
634 50);
635 break;
636 case quic::ENCRYPTION_FORWARD_SECURE:
637 UMA_HISTOGRAM_CUSTOM_COUNTS(
638 "Net.QuicSession.SendPacketSize.ForwardSecure", encrypted_length, 1,
639 kMaxOutgoingPacketSize, 50);
640 break;
641 case quic::NUM_ENCRYPTION_LEVELS:
642 NOTREACHED();
643 break;
644 }
645
646 if (!net_log_.IsCapturing())
647 return;
648 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_PACKET_SENT, [&] {
649 return NetLogQuicPacketSentParams(serialized_packet, transmission_type,
650 sent_time);
651 });
652 }
653
OnPacketLoss(quic::QuicPacketNumber lost_packet_number,quic::EncryptionLevel,quic::TransmissionType transmission_type,quic::QuicTime detection_time)654 void QuicConnectionLogger::OnPacketLoss(
655 quic::QuicPacketNumber lost_packet_number,
656 quic::EncryptionLevel /*encryption_level*/,
657 quic::TransmissionType transmission_type,
658 quic::QuicTime detection_time) {
659 if (!net_log_.IsCapturing())
660 return;
661 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_PACKET_LOST, [&] {
662 return NetLogQuicPacketLostParams(lost_packet_number, transmission_type,
663 detection_time);
664 });
665 }
666
OnPingSent()667 void QuicConnectionLogger::OnPingSent() {
668 no_packet_received_after_ping_ = true;
669 }
670
OnPacketReceived(const quic::QuicSocketAddress & self_address,const quic::QuicSocketAddress & peer_address,const quic::QuicEncryptedPacket & packet)671 void QuicConnectionLogger::OnPacketReceived(
672 const quic::QuicSocketAddress& self_address,
673 const quic::QuicSocketAddress& peer_address,
674 const quic::QuicEncryptedPacket& packet) {
675 if (local_address_from_self_.GetFamily() == ADDRESS_FAMILY_UNSPECIFIED) {
676 local_address_from_self_ = ToIPEndPoint(self_address);
677 UMA_HISTOGRAM_ENUMERATION(
678 "Net.QuicSession.ConnectionTypeFromSelf",
679 GetRealAddressFamily(ToIPEndPoint(self_address).address()),
680 ADDRESS_FAMILY_LAST);
681 }
682
683 previous_received_packet_size_ = last_received_packet_size_;
684 last_received_packet_size_ = packet.length();
685 if (!net_log_.IsCapturing())
686 return;
687 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_PACKET_RECEIVED, [&] {
688 return NetLogQuicPacketParams(self_address, peer_address, packet.length());
689 });
690 }
691
OnUnauthenticatedHeader(const quic::QuicPacketHeader & header)692 void QuicConnectionLogger::OnUnauthenticatedHeader(
693 const quic::QuicPacketHeader& header) {
694 if (!net_log_.IsCapturing())
695 return;
696 net_log_.AddEvent(
697 NetLogEventType::QUIC_SESSION_UNAUTHENTICATED_PACKET_HEADER_RECEIVED,
698 [&] {
699 return NetLogQuicPacketHeaderParams(
700 &header,
701 quic::VersionHasIetfQuicFrames(session_->transport_version()));
702 });
703 }
704
OnIncorrectConnectionId(quic::QuicConnectionId connection_id)705 void QuicConnectionLogger::OnIncorrectConnectionId(
706 quic::QuicConnectionId connection_id) {
707 ++num_incorrect_connection_ids_;
708 }
709
OnUndecryptablePacket()710 void QuicConnectionLogger::OnUndecryptablePacket() {
711 ++num_undecryptable_packets_;
712 }
713
OnDuplicatePacket(quic::QuicPacketNumber packet_number)714 void QuicConnectionLogger::OnDuplicatePacket(
715 quic::QuicPacketNumber packet_number) {
716 ++num_duplicate_packets_;
717 if (!net_log_.IsCapturing())
718 return;
719 net_log_.AddEvent(
720 NetLogEventType::QUIC_SESSION_DUPLICATE_PACKET_RECEIVED,
721 [&] { return NetLogQuicDuplicatePacketParams(packet_number); });
722 }
723
OnProtocolVersionMismatch(quic::ParsedQuicVersion received_version)724 void QuicConnectionLogger::OnProtocolVersionMismatch(
725 quic::ParsedQuicVersion received_version) {
726 // TODO(rtenneti): Add logging.
727 }
728
OnPacketHeader(const quic::QuicPacketHeader & header)729 void QuicConnectionLogger::OnPacketHeader(
730 const quic::QuicPacketHeader& header) {
731 if (!first_received_packet_number_.IsInitialized()) {
732 first_received_packet_number_ = header.packet_number;
733 } else if (header.packet_number < first_received_packet_number_) {
734 // Ignore packets with packet numbers less than
735 // first_received_packet_number_.
736 return;
737 }
738 ++num_packets_received_;
739 if (!largest_received_packet_number_.IsInitialized()) {
740 largest_received_packet_number_ = header.packet_number;
741 } else if (largest_received_packet_number_ < header.packet_number) {
742 uint64_t delta = header.packet_number - largest_received_packet_number_;
743 if (delta > 1) {
744 // There is a gap between the largest packet previously received and
745 // the current packet. This indicates either loss, or out-of-order
746 // delivery.
747 UMA_HISTOGRAM_COUNTS_1M(
748 "Net.QuicSession.PacketGapReceived",
749 static_cast<base::HistogramBase::Sample>(delta - 1));
750 }
751 largest_received_packet_number_ = header.packet_number;
752 }
753 if (header.packet_number - first_received_packet_number_ <
754 received_packets_.size()) {
755 received_packets_[header.packet_number - first_received_packet_number_] =
756 true;
757 }
758 if (last_received_packet_number_.IsInitialized() &&
759 header.packet_number < last_received_packet_number_) {
760 ++num_out_of_order_received_packets_;
761 if (previous_received_packet_size_ < last_received_packet_size_)
762 ++num_out_of_order_large_received_packets_;
763 UMA_HISTOGRAM_COUNTS_1M(
764 "Net.QuicSession.OutOfOrderGapReceived",
765 static_cast<base::HistogramBase::Sample>(last_received_packet_number_ -
766 header.packet_number));
767 } else if (no_packet_received_after_ping_) {
768 if (last_received_packet_number_.IsInitialized()) {
769 UMA_HISTOGRAM_COUNTS_1M(
770 "Net.QuicSession.PacketGapReceivedNearPing",
771 static_cast<base::HistogramBase::Sample>(
772 header.packet_number - last_received_packet_number_));
773 }
774 no_packet_received_after_ping_ = false;
775 }
776 last_received_packet_number_ = header.packet_number;
777 if (!net_log_.IsCapturing())
778 return;
779 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_PACKET_AUTHENTICATED);
780 }
781
OnStreamFrame(const quic::QuicStreamFrame & frame)782 void QuicConnectionLogger::OnStreamFrame(const quic::QuicStreamFrame& frame) {
783 if (!net_log_.IsCapturing())
784 return;
785 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_STREAM_FRAME_RECEIVED,
786 [&] { return NetLogQuicStreamFrameParams(frame); });
787 }
788
OnPathChallengeFrame(const quic::QuicPathChallengeFrame & frame)789 void QuicConnectionLogger::OnPathChallengeFrame(
790 const quic::QuicPathChallengeFrame& frame) {
791 if (!net_log_.IsCapturing())
792 return;
793 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_PATH_CHALLENGE_FRAME_RECEIVED,
794 [&] { return NetLogQuicPathData(frame.data_buffer); });
795 }
796
OnPathResponseFrame(const quic::QuicPathResponseFrame & frame)797 void QuicConnectionLogger::OnPathResponseFrame(
798 const quic::QuicPathResponseFrame& frame) {
799 if (!net_log_.IsCapturing())
800 return;
801 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_PATH_RESPONSE_FRAME_RECEIVED,
802 [&] { return NetLogQuicPathData(frame.data_buffer); });
803 }
804
OnCryptoFrame(const quic::QuicCryptoFrame & frame)805 void QuicConnectionLogger::OnCryptoFrame(const quic::QuicCryptoFrame& frame) {
806 if (!net_log_.IsCapturing())
807 return;
808 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_CRYPTO_FRAME_RECEIVED, [&] {
809 return NetLogQuicCryptoFrameParams(&frame, /*has_buffer = */ true);
810 });
811 }
812
OnStopSendingFrame(const quic::QuicStopSendingFrame & frame)813 void QuicConnectionLogger::OnStopSendingFrame(
814 const quic::QuicStopSendingFrame& frame) {
815 if (!net_log_.IsCapturing())
816 return;
817 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_STOP_SENDING_FRAME_RECEIVED,
818 [&] { return NetLogQuicStopSendingFrameParams(&frame); });
819 }
820
OnStreamsBlockedFrame(const quic::QuicStreamsBlockedFrame & frame)821 void QuicConnectionLogger::OnStreamsBlockedFrame(
822 const quic::QuicStreamsBlockedFrame& frame) {
823 if (!net_log_.IsCapturing())
824 return;
825 net_log_.AddEvent(
826 NetLogEventType::QUIC_SESSION_STREAMS_BLOCKED_FRAME_RECEIVED,
827 [&] { return NetLogQuicStreamsBlockedFrameParams(frame); });
828 }
829
OnMaxStreamsFrame(const quic::QuicMaxStreamsFrame & frame)830 void QuicConnectionLogger::OnMaxStreamsFrame(
831 const quic::QuicMaxStreamsFrame& frame) {
832 if (!net_log_.IsCapturing())
833 return;
834 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_MAX_STREAMS_FRAME_RECEIVED,
835 [&] { return NetLogQuicMaxStreamsFrameParams(frame); });
836 }
837
OnIncomingAck(quic::QuicPacketNumber ack_packet_number,quic::EncryptionLevel,const quic::QuicAckFrame & frame,quic::QuicTime ack_receive_time,quic::QuicPacketNumber largest_observed,bool rtt_updated,quic::QuicPacketNumber least_unacked_sent_packet)838 void QuicConnectionLogger::OnIncomingAck(
839 quic::QuicPacketNumber ack_packet_number,
840 quic::EncryptionLevel /*ack_decrypted_level*/,
841 const quic::QuicAckFrame& frame,
842 quic::QuicTime ack_receive_time,
843 quic::QuicPacketNumber largest_observed,
844 bool rtt_updated,
845 quic::QuicPacketNumber least_unacked_sent_packet) {
846 const size_t kApproximateLargestSoloAckBytes = 100;
847 if (last_received_packet_number_ - first_received_packet_number_ <
848 received_acks_.size() &&
849 last_received_packet_size_ < kApproximateLargestSoloAckBytes) {
850 received_acks_[last_received_packet_number_ -
851 first_received_packet_number_] = true;
852 }
853
854 if (!net_log_.IsCapturing())
855 return;
856 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_ACK_FRAME_RECEIVED,
857 [&] { return NetLogQuicAckFrameParams(&frame); });
858
859 // TODO(rch, rtenneti) sort out histograms for QUIC_VERSION_34 and above.
860 }
861
OnStopWaitingFrame(const quic::QuicStopWaitingFrame & frame)862 void QuicConnectionLogger::OnStopWaitingFrame(
863 const quic::QuicStopWaitingFrame& frame) {
864 if (!net_log_.IsCapturing())
865 return;
866 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_STOP_WAITING_FRAME_RECEIVED,
867 [&] { return NetLogQuicStopWaitingFrameParams(&frame); });
868 }
869
OnRstStreamFrame(const quic::QuicRstStreamFrame & frame)870 void QuicConnectionLogger::OnRstStreamFrame(
871 const quic::QuicRstStreamFrame& frame) {
872 base::UmaHistogramSparse("Net.QuicSession.RstStreamErrorCodeServer",
873 frame.error_code);
874 if (!net_log_.IsCapturing())
875 return;
876 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_RST_STREAM_FRAME_RECEIVED,
877 [&] { return NetLogQuicRstStreamFrameParams(&frame); });
878 }
879
OnConnectionCloseFrame(const quic::QuicConnectionCloseFrame & frame)880 void QuicConnectionLogger::OnConnectionCloseFrame(
881 const quic::QuicConnectionCloseFrame& frame) {
882 if (!net_log_.IsCapturing())
883 return;
884 net_log_.AddEvent(
885 NetLogEventType::QUIC_SESSION_CONNECTION_CLOSE_FRAME_RECEIVED,
886 [&] { return NetLogQuicConnectionCloseFrameParams(&frame); });
887 }
888
OnWindowUpdateFrame(const quic::QuicWindowUpdateFrame & frame,const quic::QuicTime & receive_time)889 void QuicConnectionLogger::OnWindowUpdateFrame(
890 const quic::QuicWindowUpdateFrame& frame,
891 const quic::QuicTime& receive_time) {
892 if (!net_log_.IsCapturing())
893 return;
894 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_WINDOW_UPDATE_FRAME_RECEIVED,
895 [&] { return NetLogQuicWindowUpdateFrameParams(&frame); });
896 }
897
OnBlockedFrame(const quic::QuicBlockedFrame & frame)898 void QuicConnectionLogger::OnBlockedFrame(const quic::QuicBlockedFrame& frame) {
899 ++num_blocked_frames_received_;
900 if (!net_log_.IsCapturing())
901 return;
902 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_BLOCKED_FRAME_RECEIVED,
903 [&] { return NetLogQuicBlockedFrameParams(&frame); });
904 }
905
OnGoAwayFrame(const quic::QuicGoAwayFrame & frame)906 void QuicConnectionLogger::OnGoAwayFrame(const quic::QuicGoAwayFrame& frame) {
907 UMA_HISTOGRAM_BOOLEAN("Net.QuicSession.GoAwayReceivedForConnectionMigration",
908 frame.error_code == quic::QUIC_ERROR_MIGRATING_PORT);
909
910 if (!net_log_.IsCapturing())
911 return;
912 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_GOAWAY_FRAME_RECEIVED,
913 [&] { return NetLogQuicGoAwayFrameParams(&frame); });
914 }
915
OnPingFrame(const quic::QuicPingFrame & frame)916 void QuicConnectionLogger::OnPingFrame(const quic::QuicPingFrame& frame) {
917 // PingFrame has no contents to log, so just record that it was received.
918 if (!net_log_.IsCapturing())
919 return;
920 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_PING_FRAME_RECEIVED);
921 }
922
OnPaddingFrame(const quic::QuicPaddingFrame & frame)923 void QuicConnectionLogger::OnPaddingFrame(const quic::QuicPaddingFrame& frame) {
924 if (!net_log_.IsCapturing())
925 return;
926 net_log_.AddEventWithIntParams(
927 NetLogEventType::QUIC_SESSION_PADDING_FRAME_RECEIVED, "num_padding_bytes",
928 frame.num_padding_bytes);
929 }
930
OnNewConnectionIdFrame(const quic::QuicNewConnectionIdFrame & frame)931 void QuicConnectionLogger::OnNewConnectionIdFrame(
932 const quic::QuicNewConnectionIdFrame& frame) {
933 if (!net_log_.IsCapturing())
934 return;
935 net_log_.AddEvent(
936 NetLogEventType::QUIC_SESSION_NEW_CONNECTION_ID_FRAME_RECEIVED,
937 [&] { return NetLogQuicNewConnectionIdFrameParams(&frame); });
938 }
939
OnNewTokenFrame(const quic::QuicNewTokenFrame & frame)940 void QuicConnectionLogger::OnNewTokenFrame(
941 const quic::QuicNewTokenFrame& frame) {
942 if (!net_log_.IsCapturing())
943 return;
944 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_NEW_TOKEN_FRAME_RECEIVED,
945 [&] { return NetLogQuicNewTokenFrameParams(&frame); });
946 }
947
OnRetireConnectionIdFrame(const quic::QuicRetireConnectionIdFrame & frame)948 void QuicConnectionLogger::OnRetireConnectionIdFrame(
949 const quic::QuicRetireConnectionIdFrame& frame) {
950 if (!net_log_.IsCapturing())
951 return;
952 net_log_.AddEvent(
953 NetLogEventType::QUIC_SESSION_RETIRE_CONNECTION_ID_FRAME_RECEIVED,
954 [&] { return NetLogQuicRetireConnectionIdFrameParams(&frame); });
955 }
956
OnMessageFrame(const quic::QuicMessageFrame & frame)957 void QuicConnectionLogger::OnMessageFrame(const quic::QuicMessageFrame& frame) {
958 if (!net_log_.IsCapturing())
959 return;
960 net_log_.AddEventWithIntParams(
961 NetLogEventType::QUIC_SESSION_MESSAGE_FRAME_RECEIVED, "message_length",
962 frame.message_length);
963 }
964
OnHandshakeDoneFrame(const quic::QuicHandshakeDoneFrame & frame)965 void QuicConnectionLogger::OnHandshakeDoneFrame(
966 const quic::QuicHandshakeDoneFrame& frame) {
967 if (!net_log_.IsCapturing())
968 return;
969 net_log_.AddEvent(
970 NetLogEventType::QUIC_SESSION_HANDSHAKE_DONE_FRAME_RECEIVED);
971 }
972
OnCoalescedPacketSent(const quic::QuicCoalescedPacket & coalesced_packet,size_t length)973 void QuicConnectionLogger::OnCoalescedPacketSent(
974 const quic::QuicCoalescedPacket& coalesced_packet,
975 size_t length) {
976 if (!net_log_.IsCapturing())
977 return;
978 net_log_.AddEventWithStringParams(
979 NetLogEventType::QUIC_SESSION_COALESCED_PACKET_SENT, "info",
980 coalesced_packet.ToString(length));
981 }
982
OnPublicResetPacket(const quic::QuicPublicResetPacket & packet)983 void QuicConnectionLogger::OnPublicResetPacket(
984 const quic::QuicPublicResetPacket& packet) {
985 UpdatePublicResetAddressMismatchHistogram(
986 local_address_from_shlo_, ToIPEndPoint(packet.client_address));
987 if (!net_log_.IsCapturing())
988 return;
989 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_PUBLIC_RESET_PACKET_RECEIVED,
990 [&] {
991 return NetLogQuicPublicResetPacketParams(
992 local_address_from_shlo_, packet.client_address);
993 });
994 }
995
OnVersionNegotiationPacket(const quic::QuicVersionNegotiationPacket & packet)996 void QuicConnectionLogger::OnVersionNegotiationPacket(
997 const quic::QuicVersionNegotiationPacket& packet) {
998 if (!net_log_.IsCapturing())
999 return;
1000 net_log_.AddEvent(
1001 NetLogEventType::QUIC_SESSION_VERSION_NEGOTIATION_PACKET_RECEIVED,
1002 [&] { return NetLogQuicVersionNegotiationPacketParams(&packet); });
1003 }
1004
OnCryptoHandshakeMessageReceived(const quic::CryptoHandshakeMessage & message)1005 void QuicConnectionLogger::OnCryptoHandshakeMessageReceived(
1006 const quic::CryptoHandshakeMessage& message) {
1007 if (message.tag() == quic::kSHLO) {
1008 quiche::QuicheStringPiece address;
1009 quic::QuicSocketAddressCoder decoder;
1010 if (message.GetStringPiece(quic::kCADR, &address) &&
1011 decoder.Decode(address.data(), address.size())) {
1012 local_address_from_shlo_ =
1013 IPEndPoint(ToIPAddress(decoder.ip()), decoder.port());
1014 UMA_HISTOGRAM_ENUMERATION(
1015 "Net.QuicSession.ConnectionTypeFromPeer",
1016 GetRealAddressFamily(local_address_from_shlo_.address()),
1017 ADDRESS_FAMILY_LAST);
1018
1019 int sample = GetAddressMismatch(local_address_from_shlo_,
1020 local_address_from_self_);
1021 // We are seemingly talking to an older server that does not support the
1022 // feature, so we can't report the results in the histogram.
1023 if (sample >= 0) {
1024 UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.SelfShloAddressMismatch",
1025 static_cast<QuicAddressMismatch>(sample),
1026 QUIC_ADDRESS_MISMATCH_MAX);
1027 }
1028 }
1029 }
1030 if (!net_log_.IsCapturing())
1031 return;
1032 net_log_.AddEvent(
1033 NetLogEventType::QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_RECEIVED,
1034 [&] { return NetLogQuicCryptoHandshakeMessageParams(&message); });
1035 }
1036
OnCryptoHandshakeMessageSent(const quic::CryptoHandshakeMessage & message)1037 void QuicConnectionLogger::OnCryptoHandshakeMessageSent(
1038 const quic::CryptoHandshakeMessage& message) {
1039 if (!net_log_.IsCapturing())
1040 return;
1041 net_log_.AddEvent(
1042 NetLogEventType::QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_SENT,
1043 [&] { return NetLogQuicCryptoHandshakeMessageParams(&message); });
1044 }
1045
OnConnectionClosed(const quic::QuicConnectionCloseFrame & frame,quic::ConnectionCloseSource source)1046 void QuicConnectionLogger::OnConnectionClosed(
1047 const quic::QuicConnectionCloseFrame& frame,
1048 quic::ConnectionCloseSource source) {
1049 if (!net_log_.IsCapturing())
1050 return;
1051 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_CLOSED, [&] {
1052 return NetLogQuicOnConnectionClosedParams(frame.quic_error_code,
1053 frame.error_details, source);
1054 });
1055 }
1056
OnSuccessfulVersionNegotiation(const quic::ParsedQuicVersion & version)1057 void QuicConnectionLogger::OnSuccessfulVersionNegotiation(
1058 const quic::ParsedQuicVersion& version) {
1059 if (!net_log_.IsCapturing())
1060 return;
1061 string quic_version = quic::ParsedQuicVersionToString(version);
1062 net_log_.AddEventWithStringParams(
1063 NetLogEventType::QUIC_SESSION_VERSION_NEGOTIATED, "version",
1064 quic_version);
1065 }
1066
UpdateReceivedFrameCounts(quic::QuicStreamId stream_id,int num_frames_received,int num_duplicate_frames_received)1067 void QuicConnectionLogger::UpdateReceivedFrameCounts(
1068 quic::QuicStreamId stream_id,
1069 int num_frames_received,
1070 int num_duplicate_frames_received) {
1071 if (!quic::QuicUtils::IsCryptoStreamId(session_->transport_version(),
1072 stream_id)) {
1073 num_frames_received_ += num_frames_received;
1074 num_duplicate_frames_received_ += num_duplicate_frames_received;
1075 }
1076 }
1077
OnCertificateVerified(const CertVerifyResult & result)1078 void QuicConnectionLogger::OnCertificateVerified(
1079 const CertVerifyResult& result) {
1080 if (!net_log_.IsCapturing())
1081 return;
1082 if (result.cert_status == CERT_STATUS_INVALID) {
1083 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_CERTIFICATE_VERIFY_FAILED);
1084 return;
1085 }
1086 net_log_.AddEvent(NetLogEventType::QUIC_SESSION_CERTIFICATE_VERIFIED, [&] {
1087 return NetLogQuicCertificateVerifiedParams(result.verified_cert);
1088 });
1089 }
1090
Get6PacketHistogram(const char * which_6) const1091 base::HistogramBase* QuicConnectionLogger::Get6PacketHistogram(
1092 const char* which_6) const {
1093 // This histogram takes a binary encoding of the 6 consecutive packets
1094 // received. As a result, there are 64 possible sample-patterns.
1095 string prefix("Net.QuicSession.6PacketsPatternsReceived_");
1096 return base::LinearHistogram::FactoryGet(
1097 prefix + which_6 + connection_description_, 1, 64, 65,
1098 base::HistogramBase::kUmaTargetedHistogramFlag);
1099 }
1100
ReceivedPacketLossRate() const1101 float QuicConnectionLogger::ReceivedPacketLossRate() const {
1102 if (!largest_received_packet_number_.IsInitialized())
1103 return 0.0f;
1104 float num_packets =
1105 largest_received_packet_number_ - first_received_packet_number_ + 1;
1106 float num_missing = num_packets - num_packets_received_;
1107 return num_missing / num_packets;
1108 }
1109
OnRttChanged(quic::QuicTime::Delta rtt) const1110 void QuicConnectionLogger::OnRttChanged(quic::QuicTime::Delta rtt) const {
1111 // Notify socket performance watcher of the updated RTT value.
1112 if (!socket_performance_watcher_)
1113 return;
1114
1115 int64_t microseconds = rtt.ToMicroseconds();
1116 if (microseconds != 0 &&
1117 socket_performance_watcher_->ShouldNotifyUpdatedRTT()) {
1118 socket_performance_watcher_->OnUpdatedRTTAvailable(
1119 base::TimeDelta::FromMicroseconds(rtt.ToMicroseconds()));
1120 }
1121 }
1122
RecordAggregatePacketLossRate() const1123 void QuicConnectionLogger::RecordAggregatePacketLossRate() const {
1124 // For short connections under 22 packets in length, we'll rely on the
1125 // Net.QuicSession.21CumulativePacketsReceived_* histogram to indicate packet
1126 // loss rates. This way we avoid tremendously anomalous contributions to our
1127 // histogram. (e.g., if we only got 5 packets, but lost 1, we'd otherwise
1128 // record a 20% loss in this histogram!). We may still get some strange data
1129 // (1 loss in 22 is still high :-/).
1130 if (!largest_received_packet_number_.IsInitialized() ||
1131 largest_received_packet_number_ - first_received_packet_number_ < 22)
1132 return;
1133
1134 string prefix("Net.QuicSession.PacketLossRate_");
1135 base::HistogramBase* histogram = base::Histogram::FactoryGet(
1136 prefix + connection_description_, 1, 1000, 75,
1137 base::HistogramBase::kUmaTargetedHistogramFlag);
1138 histogram->Add(static_cast<base::HistogramBase::Sample>(
1139 ReceivedPacketLossRate() * 1000));
1140 }
1141
1142 } // namespace net
1143