1 // Copyright (c) 2013 The Chromium Authors. All rights reserved.
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
4
5 #include "net/quic/quic_connection_logger.h"
6
7 #include "base/bind.h"
8 #include "base/callback.h"
9 #include "base/metrics/histogram.h"
10 #include "base/metrics/sparse_histogram.h"
11 #include "base/strings/string_number_conversions.h"
12 #include "base/values.h"
13 #include "net/base/net_log.h"
14 #include "net/quic/crypto/crypto_handshake.h"
15
16 using std::string;
17
18 namespace net {
19
20 namespace {
21
NetLogQuicPacketCallback(const IPEndPoint * self_address,const IPEndPoint * peer_address,size_t packet_size,NetLog::LogLevel)22 base::Value* NetLogQuicPacketCallback(const IPEndPoint* self_address,
23 const IPEndPoint* peer_address,
24 size_t packet_size,
25 NetLog::LogLevel /* log_level */) {
26 base::DictionaryValue* dict = new base::DictionaryValue();
27 dict->SetString("self_address", self_address->ToString());
28 dict->SetString("peer_address", peer_address->ToString());
29 dict->SetInteger("size", packet_size);
30 return dict;
31 }
32
NetLogQuicPacketSentCallback(QuicPacketSequenceNumber sequence_number,EncryptionLevel level,size_t packet_size,WriteResult result,NetLog::LogLevel)33 base::Value* NetLogQuicPacketSentCallback(
34 QuicPacketSequenceNumber sequence_number,
35 EncryptionLevel level,
36 size_t packet_size,
37 WriteResult result,
38 NetLog::LogLevel /* log_level */) {
39 base::DictionaryValue* dict = new base::DictionaryValue();
40 dict->SetInteger("encryption_level", level);
41 dict->SetString("packet_sequence_number",
42 base::Uint64ToString(sequence_number));
43 dict->SetInteger("size", packet_size);
44 if (result.status != WRITE_STATUS_OK) {
45 dict->SetInteger("net_error", result.error_code);
46 }
47 return dict;
48 }
49
NetLogQuicPacketRetransmittedCallback(QuicPacketSequenceNumber old_sequence_number,QuicPacketSequenceNumber new_sequence_number,NetLog::LogLevel)50 base::Value* NetLogQuicPacketRetransmittedCallback(
51 QuicPacketSequenceNumber old_sequence_number,
52 QuicPacketSequenceNumber new_sequence_number,
53 NetLog::LogLevel /* log_level */) {
54 base::DictionaryValue* dict = new base::DictionaryValue();
55 dict->SetString("old_packet_sequence_number",
56 base::Uint64ToString(old_sequence_number));
57 dict->SetString("new_packet_sequence_number",
58 base::Uint64ToString(new_sequence_number));
59 return dict;
60 }
61
NetLogQuicPacketHeaderCallback(const QuicPacketHeader * header,NetLog::LogLevel)62 base::Value* NetLogQuicPacketHeaderCallback(const QuicPacketHeader* header,
63 NetLog::LogLevel /* log_level */) {
64 base::DictionaryValue* dict = new base::DictionaryValue();
65 dict->SetString("guid",
66 base::Uint64ToString(header->public_header.guid));
67 dict->SetInteger("reset_flag", header->public_header.reset_flag);
68 dict->SetInteger("version_flag", header->public_header.version_flag);
69 dict->SetString("packet_sequence_number",
70 base::Uint64ToString(header->packet_sequence_number));
71 dict->SetInteger("entropy_flag", header->entropy_flag);
72 dict->SetInteger("fec_flag", header->fec_flag);
73 dict->SetInteger("fec_group", header->fec_group);
74 return dict;
75 }
76
NetLogQuicStreamFrameCallback(const QuicStreamFrame * frame,NetLog::LogLevel)77 base::Value* NetLogQuicStreamFrameCallback(const QuicStreamFrame* frame,
78 NetLog::LogLevel /* log_level */) {
79 base::DictionaryValue* dict = new base::DictionaryValue();
80 dict->SetInteger("stream_id", frame->stream_id);
81 dict->SetBoolean("fin", frame->fin);
82 dict->SetString("offset", base::Uint64ToString(frame->offset));
83 dict->SetInteger("length", frame->data.TotalBufferSize());
84 return dict;
85 }
86
NetLogQuicAckFrameCallback(const QuicAckFrame * frame,NetLog::LogLevel)87 base::Value* NetLogQuicAckFrameCallback(const QuicAckFrame* frame,
88 NetLog::LogLevel /* log_level */) {
89 base::DictionaryValue* dict = new base::DictionaryValue();
90 base::DictionaryValue* sent_info = new base::DictionaryValue();
91 dict->Set("sent_info", sent_info);
92 sent_info->SetString("least_unacked",
93 base::Uint64ToString(frame->sent_info.least_unacked));
94 base::DictionaryValue* received_info = new base::DictionaryValue();
95 dict->Set("received_info", received_info);
96 received_info->SetString(
97 "largest_observed",
98 base::Uint64ToString(frame->received_info.largest_observed));
99 base::ListValue* missing = new base::ListValue();
100 received_info->Set("missing_packets", missing);
101 const SequenceNumberSet& missing_packets =
102 frame->received_info.missing_packets;
103 for (SequenceNumberSet::const_iterator it = missing_packets.begin();
104 it != missing_packets.end(); ++it) {
105 missing->AppendString(base::Uint64ToString(*it));
106 }
107 return dict;
108 }
109
NetLogQuicCongestionFeedbackFrameCallback(const QuicCongestionFeedbackFrame * frame,NetLog::LogLevel)110 base::Value* NetLogQuicCongestionFeedbackFrameCallback(
111 const QuicCongestionFeedbackFrame* frame,
112 NetLog::LogLevel /* log_level */) {
113 base::DictionaryValue* dict = new base::DictionaryValue();
114 switch (frame->type) {
115 case kInterArrival: {
116 dict->SetString("type", "InterArrival");
117 dict->SetInteger("accumulated_number_of_lost_packets",
118 frame->inter_arrival.accumulated_number_of_lost_packets);
119 base::ListValue* received = new base::ListValue();
120 dict->Set("received_packets", received);
121 for (TimeMap::const_iterator it =
122 frame->inter_arrival.received_packet_times.begin();
123 it != frame->inter_arrival.received_packet_times.end(); ++it) {
124 std::string value = base::Uint64ToString(it->first) + "@" +
125 base::Uint64ToString(it->second.ToDebuggingValue());
126 received->AppendString(value);
127 }
128 break;
129 }
130 case kFixRate:
131 dict->SetString("type", "FixRate");
132 dict->SetInteger("bitrate_in_bytes_per_second",
133 frame->fix_rate.bitrate.ToBytesPerSecond());
134 break;
135 case kTCP:
136 dict->SetString("type", "TCP");
137 dict->SetInteger("accumulated_number_of_lost_packets",
138 frame->tcp.accumulated_number_of_lost_packets);
139 dict->SetInteger("receive_window", frame->tcp.receive_window);
140 break;
141 }
142
143 return dict;
144 }
145
NetLogQuicRstStreamFrameCallback(const QuicRstStreamFrame * frame,NetLog::LogLevel)146 base::Value* NetLogQuicRstStreamFrameCallback(
147 const QuicRstStreamFrame* frame,
148 NetLog::LogLevel /* log_level */) {
149 base::DictionaryValue* dict = new base::DictionaryValue();
150 dict->SetInteger("stream_id", frame->stream_id);
151 dict->SetInteger("quic_rst_stream_error", frame->error_code);
152 dict->SetString("details", frame->error_details);
153 return dict;
154 }
155
NetLogQuicConnectionCloseFrameCallback(const QuicConnectionCloseFrame * frame,NetLog::LogLevel)156 base::Value* NetLogQuicConnectionCloseFrameCallback(
157 const QuicConnectionCloseFrame* frame,
158 NetLog::LogLevel /* log_level */) {
159 base::DictionaryValue* dict = new base::DictionaryValue();
160 dict->SetInteger("quic_error", frame->error_code);
161 dict->SetString("details", frame->error_details);
162 return dict;
163 }
164
NetLogQuicVersionNegotiationPacketCallback(const QuicVersionNegotiationPacket * packet,NetLog::LogLevel)165 base::Value* NetLogQuicVersionNegotiationPacketCallback(
166 const QuicVersionNegotiationPacket* packet,
167 NetLog::LogLevel /* log_level */) {
168 base::DictionaryValue* dict = new base::DictionaryValue();
169 base::ListValue* versions = new base::ListValue();
170 dict->Set("versions", versions);
171 for (QuicVersionVector::const_iterator it = packet->versions.begin();
172 it != packet->versions.end(); ++it) {
173 versions->AppendString(QuicVersionToString(*it));
174 }
175 return dict;
176 }
177
NetLogQuicCryptoHandshakeMessageCallback(const CryptoHandshakeMessage * message,NetLog::LogLevel)178 base::Value* NetLogQuicCryptoHandshakeMessageCallback(
179 const CryptoHandshakeMessage* message,
180 NetLog::LogLevel /* log_level */) {
181 base::DictionaryValue* dict = new base::DictionaryValue();
182 dict->SetString("quic_crypto_handshake_message", message->DebugString());
183 return dict;
184 }
185
NetLogQuicOnConnectionClosedCallback(QuicErrorCode error,bool from_peer,NetLog::LogLevel)186 base::Value* NetLogQuicOnConnectionClosedCallback(
187 QuicErrorCode error,
188 bool from_peer,
189 NetLog::LogLevel /* log_level */) {
190 base::DictionaryValue* dict = new base::DictionaryValue();
191 dict->SetInteger("quic_error", error);
192 dict->SetBoolean("from_peer", from_peer);
193 return dict;
194 }
195
UpdatePacketGapSentHistogram(size_t num_consecutive_missing_packets)196 void UpdatePacketGapSentHistogram(size_t num_consecutive_missing_packets) {
197 UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapSent",
198 num_consecutive_missing_packets);
199 }
200
201 } // namespace
202
QuicConnectionLogger(const BoundNetLog & net_log)203 QuicConnectionLogger::QuicConnectionLogger(const BoundNetLog& net_log)
204 : net_log_(net_log),
205 last_received_packet_sequence_number_(0),
206 largest_received_packet_sequence_number_(0),
207 largest_received_missing_packet_sequence_number_(0),
208 out_of_order_recieved_packet_count_(0) {
209 }
210
~QuicConnectionLogger()211 QuicConnectionLogger::~QuicConnectionLogger() {
212 UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderPacketsReceived",
213 out_of_order_recieved_packet_count_);
214 }
215
OnFrameAddedToPacket(const QuicFrame & frame)216 void QuicConnectionLogger::OnFrameAddedToPacket(const QuicFrame& frame) {
217 switch (frame.type) {
218 case PADDING_FRAME:
219 break;
220 case STREAM_FRAME:
221 net_log_.AddEvent(
222 NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_SENT,
223 base::Bind(&NetLogQuicStreamFrameCallback, frame.stream_frame));
224 break;
225 case ACK_FRAME:
226 net_log_.AddEvent(
227 NetLog::TYPE_QUIC_SESSION_ACK_FRAME_SENT,
228 base::Bind(&NetLogQuicAckFrameCallback, frame.ack_frame));
229 break;
230 case CONGESTION_FEEDBACK_FRAME:
231 net_log_.AddEvent(
232 NetLog::TYPE_QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_SENT,
233 base::Bind(&NetLogQuicCongestionFeedbackFrameCallback,
234 frame.congestion_feedback_frame));
235 break;
236 case RST_STREAM_FRAME:
237 UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeClient",
238 frame.rst_stream_frame->error_code);
239 net_log_.AddEvent(
240 NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_SENT,
241 base::Bind(&NetLogQuicRstStreamFrameCallback,
242 frame.rst_stream_frame));
243 break;
244 case CONNECTION_CLOSE_FRAME:
245 net_log_.AddEvent(
246 NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_SENT,
247 base::Bind(&NetLogQuicConnectionCloseFrameCallback,
248 frame.connection_close_frame));
249 break;
250 case GOAWAY_FRAME:
251 break;
252 default:
253 DCHECK(false) << "Illegal frame type: " << frame.type;
254 }
255 }
256
OnPacketSent(QuicPacketSequenceNumber sequence_number,EncryptionLevel level,const QuicEncryptedPacket & packet,WriteResult result)257 void QuicConnectionLogger::OnPacketSent(
258 QuicPacketSequenceNumber sequence_number,
259 EncryptionLevel level,
260 const QuicEncryptedPacket& packet,
261 WriteResult result) {
262 net_log_.AddEvent(
263 NetLog::TYPE_QUIC_SESSION_PACKET_SENT,
264 base::Bind(&NetLogQuicPacketSentCallback, sequence_number, level,
265 packet.length(), result));
266 }
267
OnPacketRetransmitted(QuicPacketSequenceNumber old_sequence_number,QuicPacketSequenceNumber new_sequence_number)268 void QuicConnectionLogger:: OnPacketRetransmitted(
269 QuicPacketSequenceNumber old_sequence_number,
270 QuicPacketSequenceNumber new_sequence_number) {
271 net_log_.AddEvent(
272 NetLog::TYPE_QUIC_SESSION_PACKET_RETRANSMITTED,
273 base::Bind(&NetLogQuicPacketRetransmittedCallback,
274 old_sequence_number, new_sequence_number));
275 }
276
OnPacketReceived(const IPEndPoint & self_address,const IPEndPoint & peer_address,const QuicEncryptedPacket & packet)277 void QuicConnectionLogger::OnPacketReceived(const IPEndPoint& self_address,
278 const IPEndPoint& peer_address,
279 const QuicEncryptedPacket& packet) {
280 net_log_.AddEvent(
281 NetLog::TYPE_QUIC_SESSION_PACKET_RECEIVED,
282 base::Bind(&NetLogQuicPacketCallback, &self_address, &peer_address,
283 packet.length()));
284 }
285
OnProtocolVersionMismatch(QuicVersion received_version)286 void QuicConnectionLogger::OnProtocolVersionMismatch(
287 QuicVersion received_version) {
288 // TODO(rtenneti): Add logging.
289 }
290
OnPacketHeader(const QuicPacketHeader & header)291 void QuicConnectionLogger::OnPacketHeader(const QuicPacketHeader& header) {
292 net_log_.AddEvent(
293 NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_RECEIVED,
294 base::Bind(&NetLogQuicPacketHeaderCallback, &header));
295 if (largest_received_packet_sequence_number_ <
296 header.packet_sequence_number) {
297 QuicPacketSequenceNumber delta = header.packet_sequence_number -
298 largest_received_packet_sequence_number_;
299 if (delta > 1) {
300 // There is a gap between the largest packet previously received and
301 // the current packet. This indicates either loss, or out-of-order
302 // delivery.
303 UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapReceived", delta - 1);
304 }
305 largest_received_packet_sequence_number_ = header.packet_sequence_number;
306 }
307 if (header.packet_sequence_number < last_received_packet_sequence_number_) {
308 ++out_of_order_recieved_packet_count_;
309 UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderGapReceived",
310 last_received_packet_sequence_number_ -
311 header.packet_sequence_number);
312 }
313 last_received_packet_sequence_number_ = header.packet_sequence_number;
314 }
315
OnStreamFrame(const QuicStreamFrame & frame)316 void QuicConnectionLogger::OnStreamFrame(const QuicStreamFrame& frame) {
317 net_log_.AddEvent(
318 NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_RECEIVED,
319 base::Bind(&NetLogQuicStreamFrameCallback, &frame));
320 }
321
OnAckFrame(const QuicAckFrame & frame)322 void QuicConnectionLogger::OnAckFrame(const QuicAckFrame& frame) {
323 net_log_.AddEvent(
324 NetLog::TYPE_QUIC_SESSION_ACK_FRAME_RECEIVED,
325 base::Bind(&NetLogQuicAckFrameCallback, &frame));
326
327 if (frame.received_info.missing_packets.empty())
328 return;
329
330 SequenceNumberSet missing_packets = frame.received_info.missing_packets;
331 SequenceNumberSet::const_iterator it = missing_packets.lower_bound(
332 largest_received_missing_packet_sequence_number_);
333 if (it == missing_packets.end())
334 return;
335
336 if (*it == largest_received_missing_packet_sequence_number_) {
337 ++it;
338 if (it == missing_packets.end())
339 return;
340 }
341 // Scan through the list and log consecutive ranges of missing packets.
342 size_t num_consecutive_missing_packets = 0;
343 QuicPacketSequenceNumber previous_missing_packet = *it - 1;
344 while (it != missing_packets.end()) {
345 if (previous_missing_packet == *it - 1) {
346 ++num_consecutive_missing_packets;
347 } else {
348 DCHECK_NE(0u, num_consecutive_missing_packets);
349 UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
350 // Make sure this packet it included in the count.
351 num_consecutive_missing_packets = 1;
352 }
353 previous_missing_packet = *it;
354 ++it;
355 }
356 if (num_consecutive_missing_packets != 0) {
357 UpdatePacketGapSentHistogram(num_consecutive_missing_packets);
358 }
359 largest_received_missing_packet_sequence_number_ =
360 *missing_packets.rbegin();
361 }
362
OnCongestionFeedbackFrame(const QuicCongestionFeedbackFrame & frame)363 void QuicConnectionLogger::OnCongestionFeedbackFrame(
364 const QuicCongestionFeedbackFrame& frame) {
365 net_log_.AddEvent(
366 NetLog::TYPE_QUIC_SESSION_CONGESTION_FEEDBACK_FRAME_RECEIVED,
367 base::Bind(&NetLogQuicCongestionFeedbackFrameCallback, &frame));
368 }
369
OnRstStreamFrame(const QuicRstStreamFrame & frame)370 void QuicConnectionLogger::OnRstStreamFrame(const QuicRstStreamFrame& frame) {
371 UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeServer",
372 frame.error_code);
373 net_log_.AddEvent(
374 NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_RECEIVED,
375 base::Bind(&NetLogQuicRstStreamFrameCallback, &frame));
376 }
377
OnConnectionCloseFrame(const QuicConnectionCloseFrame & frame)378 void QuicConnectionLogger::OnConnectionCloseFrame(
379 const QuicConnectionCloseFrame& frame) {
380 net_log_.AddEvent(
381 NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_RECEIVED,
382 base::Bind(&NetLogQuicConnectionCloseFrameCallback, &frame));
383 }
384
OnPublicResetPacket(const QuicPublicResetPacket & packet)385 void QuicConnectionLogger::OnPublicResetPacket(
386 const QuicPublicResetPacket& packet) {
387 net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PUBLIC_RESET_PACKET_RECEIVED);
388 }
389
OnVersionNegotiationPacket(const QuicVersionNegotiationPacket & packet)390 void QuicConnectionLogger::OnVersionNegotiationPacket(
391 const QuicVersionNegotiationPacket& packet) {
392 net_log_.AddEvent(
393 NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATION_PACKET_RECEIVED,
394 base::Bind(&NetLogQuicVersionNegotiationPacketCallback, &packet));
395 }
396
OnRevivedPacket(const QuicPacketHeader & revived_header,base::StringPiece payload)397 void QuicConnectionLogger::OnRevivedPacket(
398 const QuicPacketHeader& revived_header,
399 base::StringPiece payload) {
400 net_log_.AddEvent(
401 NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_REVIVED,
402 base::Bind(&NetLogQuicPacketHeaderCallback, &revived_header));
403 }
404
OnCryptoHandshakeMessageReceived(const CryptoHandshakeMessage & message)405 void QuicConnectionLogger::OnCryptoHandshakeMessageReceived(
406 const CryptoHandshakeMessage& message) {
407 net_log_.AddEvent(
408 NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_RECEIVED,
409 base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
410 }
411
OnCryptoHandshakeMessageSent(const CryptoHandshakeMessage & message)412 void QuicConnectionLogger::OnCryptoHandshakeMessageSent(
413 const CryptoHandshakeMessage& message) {
414 net_log_.AddEvent(
415 NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_SENT,
416 base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message));
417 }
418
OnConnectionClosed(QuicErrorCode error,bool from_peer)419 void QuicConnectionLogger::OnConnectionClosed(QuicErrorCode error,
420 bool from_peer) {
421 net_log_.AddEvent(
422 NetLog::TYPE_QUIC_SESSION_CLOSED,
423 base::Bind(&NetLogQuicOnConnectionClosedCallback, error, from_peer));
424 }
425
OnSuccessfulVersionNegotiation(const QuicVersion & version)426 void QuicConnectionLogger::OnSuccessfulVersionNegotiation(
427 const QuicVersion& version) {
428 string quic_version = QuicVersionToString(version);
429 net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATED,
430 NetLog::StringCallback("version", &quic_version));
431 }
432
433 } // namespace net
434