1 // Copyright (c) 2018 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 "quiche/quic/core/quic_trace_visitor.h"
6
7 #include <string>
8
9 #include "quiche/quic/core/quic_types.h"
10 #include "quiche/common/quiche_endian.h"
11
12 namespace quic {
13
EncryptionLevelToProto(EncryptionLevel level)14 quic_trace::EncryptionLevel EncryptionLevelToProto(EncryptionLevel level) {
15 switch (level) {
16 case ENCRYPTION_INITIAL:
17 return quic_trace::ENCRYPTION_INITIAL;
18 case ENCRYPTION_HANDSHAKE:
19 return quic_trace::ENCRYPTION_HANDSHAKE;
20 case ENCRYPTION_ZERO_RTT:
21 return quic_trace::ENCRYPTION_0RTT;
22 case ENCRYPTION_FORWARD_SECURE:
23 return quic_trace::ENCRYPTION_1RTT;
24 case NUM_ENCRYPTION_LEVELS:
25 QUIC_BUG(EncryptionLevelToProto.Invalid)
26 << "Invalid encryption level specified";
27 return quic_trace::ENCRYPTION_UNKNOWN;
28 }
29 QUIC_BUG(EncryptionLevelToProto.Unknown)
30 << "Unknown encryption level specified " << static_cast<int>(level);
31 return quic_trace::ENCRYPTION_UNKNOWN;
32 }
33
QuicTraceVisitor(const QuicConnection * connection)34 QuicTraceVisitor::QuicTraceVisitor(const QuicConnection* connection)
35 : connection_(connection),
36 start_time_(connection_->clock()->ApproximateNow()) {
37 std::string binary_connection_id(connection->connection_id().data(),
38 connection->connection_id().length());
39 // We assume that the connection ID in gQUIC is equivalent to the
40 // server-chosen client-selected ID.
41 switch (connection->perspective()) {
42 case Perspective::IS_CLIENT:
43 trace_.set_destination_connection_id(binary_connection_id);
44 break;
45 case Perspective::IS_SERVER:
46 trace_.set_source_connection_id(binary_connection_id);
47 break;
48 }
49 }
50
OnPacketSent(QuicPacketNumber packet_number,QuicPacketLength packet_length,bool,TransmissionType,EncryptionLevel encryption_level,const QuicFrames & retransmittable_frames,const QuicFrames &,QuicTime sent_time,uint32_t)51 void QuicTraceVisitor::OnPacketSent(
52 QuicPacketNumber packet_number, QuicPacketLength packet_length,
53 bool /*has_crypto_handshake*/, TransmissionType /*transmission_type*/,
54 EncryptionLevel encryption_level, const QuicFrames& retransmittable_frames,
55 const QuicFrames& /*nonretransmittable_frames*/, QuicTime sent_time,
56 uint32_t /*batch_id*/) {
57 quic_trace::Event* event = trace_.add_events();
58 event->set_event_type(quic_trace::PACKET_SENT);
59 event->set_time_us(ConvertTimestampToRecordedFormat(sent_time));
60 event->set_packet_number(packet_number.ToUint64());
61 event->set_packet_size(packet_length);
62 event->set_encryption_level(EncryptionLevelToProto(encryption_level));
63
64 for (const QuicFrame& frame : retransmittable_frames) {
65 switch (frame.type) {
66 case STREAM_FRAME:
67 case RST_STREAM_FRAME:
68 case CONNECTION_CLOSE_FRAME:
69 case WINDOW_UPDATE_FRAME:
70 case BLOCKED_FRAME:
71 case PING_FRAME:
72 case HANDSHAKE_DONE_FRAME:
73 case ACK_FREQUENCY_FRAME:
74 PopulateFrameInfo(frame, event->add_frames());
75 break;
76
77 case PADDING_FRAME:
78 case MTU_DISCOVERY_FRAME:
79 case STOP_WAITING_FRAME:
80 case ACK_FRAME:
81 QUIC_BUG(quic_bug_12732_1)
82 << "Frames of type are not retransmittable and are not supposed "
83 "to be in retransmittable_frames";
84 break;
85
86 // New IETF frames, not used in current gQUIC version.
87 case NEW_CONNECTION_ID_FRAME:
88 case RETIRE_CONNECTION_ID_FRAME:
89 case MAX_STREAMS_FRAME:
90 case STREAMS_BLOCKED_FRAME:
91 case PATH_RESPONSE_FRAME:
92 case PATH_CHALLENGE_FRAME:
93 case STOP_SENDING_FRAME:
94 case MESSAGE_FRAME:
95 case CRYPTO_FRAME:
96 case NEW_TOKEN_FRAME:
97 case RESET_STREAM_AT_FRAME:
98 break;
99
100 // Ignore gQUIC-specific frames.
101 case GOAWAY_FRAME:
102 break;
103
104 case NUM_FRAME_TYPES:
105 QUIC_BUG(quic_bug_10284_2) << "Unknown frame type encountered";
106 break;
107 }
108 }
109
110 // Output PCC DebugState on packet sent for analysis.
111 if (connection_->sent_packet_manager()
112 .GetSendAlgorithm()
113 ->GetCongestionControlType() == kPCC) {
114 PopulateTransportState(event->mutable_transport_state());
115 }
116 }
117
PopulateFrameInfo(const QuicFrame & frame,quic_trace::Frame * frame_record)118 void QuicTraceVisitor::PopulateFrameInfo(const QuicFrame& frame,
119 quic_trace::Frame* frame_record) {
120 switch (frame.type) {
121 case STREAM_FRAME: {
122 frame_record->set_frame_type(quic_trace::STREAM);
123
124 quic_trace::StreamFrameInfo* info =
125 frame_record->mutable_stream_frame_info();
126 info->set_stream_id(frame.stream_frame.stream_id);
127 info->set_fin(frame.stream_frame.fin);
128 info->set_offset(frame.stream_frame.offset);
129 info->set_length(frame.stream_frame.data_length);
130 break;
131 }
132
133 case ACK_FRAME: {
134 frame_record->set_frame_type(quic_trace::ACK);
135
136 quic_trace::AckInfo* info = frame_record->mutable_ack_info();
137 info->set_ack_delay_us(frame.ack_frame->ack_delay_time.ToMicroseconds());
138 for (const auto& interval : frame.ack_frame->packets) {
139 quic_trace::AckBlock* block = info->add_acked_packets();
140 // We record intervals as [a, b], whereas the in-memory representation
141 // we currently use is [a, b).
142 block->set_first_packet(interval.min().ToUint64());
143 block->set_last_packet(interval.max().ToUint64() - 1);
144 }
145 break;
146 }
147
148 case RST_STREAM_FRAME: {
149 frame_record->set_frame_type(quic_trace::RESET_STREAM);
150
151 quic_trace::ResetStreamInfo* info =
152 frame_record->mutable_reset_stream_info();
153 info->set_stream_id(frame.rst_stream_frame->stream_id);
154 info->set_final_offset(frame.rst_stream_frame->byte_offset);
155 info->set_application_error_code(frame.rst_stream_frame->error_code);
156 break;
157 }
158
159 case CONNECTION_CLOSE_FRAME: {
160 frame_record->set_frame_type(quic_trace::CONNECTION_CLOSE);
161
162 quic_trace::CloseInfo* info = frame_record->mutable_close_info();
163 info->set_error_code(frame.connection_close_frame->quic_error_code);
164 info->set_reason_phrase(frame.connection_close_frame->error_details);
165 info->set_close_type(static_cast<quic_trace::CloseType>(
166 frame.connection_close_frame->close_type));
167 info->set_transport_close_frame_type(
168 frame.connection_close_frame->transport_close_frame_type);
169 break;
170 }
171
172 case GOAWAY_FRAME:
173 // Do not bother logging this since the frame in question is
174 // gQUIC-specific.
175 break;
176
177 case WINDOW_UPDATE_FRAME: {
178 bool is_connection = frame.window_update_frame.stream_id == 0;
179 frame_record->set_frame_type(is_connection ? quic_trace::MAX_DATA
180 : quic_trace::MAX_STREAM_DATA);
181
182 quic_trace::FlowControlInfo* info =
183 frame_record->mutable_flow_control_info();
184 info->set_max_data(frame.window_update_frame.max_data);
185 if (!is_connection) {
186 info->set_stream_id(frame.window_update_frame.stream_id);
187 }
188 break;
189 }
190
191 case BLOCKED_FRAME: {
192 bool is_connection = frame.blocked_frame.stream_id == 0;
193 frame_record->set_frame_type(is_connection ? quic_trace::BLOCKED
194 : quic_trace::STREAM_BLOCKED);
195
196 quic_trace::FlowControlInfo* info =
197 frame_record->mutable_flow_control_info();
198 if (!is_connection) {
199 info->set_stream_id(frame.window_update_frame.stream_id);
200 }
201 break;
202 }
203
204 case PING_FRAME:
205 case MTU_DISCOVERY_FRAME:
206 case HANDSHAKE_DONE_FRAME:
207 frame_record->set_frame_type(quic_trace::PING);
208 break;
209
210 case PADDING_FRAME:
211 frame_record->set_frame_type(quic_trace::PADDING);
212 break;
213
214 case STOP_WAITING_FRAME:
215 // We're going to pretend those do not exist.
216 break;
217
218 // New IETF frames, not used in current gQUIC version.
219 case NEW_CONNECTION_ID_FRAME:
220 case RETIRE_CONNECTION_ID_FRAME:
221 case MAX_STREAMS_FRAME:
222 case STREAMS_BLOCKED_FRAME:
223 case PATH_RESPONSE_FRAME:
224 case PATH_CHALLENGE_FRAME:
225 case STOP_SENDING_FRAME:
226 case MESSAGE_FRAME:
227 case CRYPTO_FRAME:
228 case NEW_TOKEN_FRAME:
229 case ACK_FREQUENCY_FRAME:
230 case RESET_STREAM_AT_FRAME:
231 break;
232
233 case NUM_FRAME_TYPES:
234 QUIC_BUG(quic_bug_10284_3) << "Unknown frame type encountered";
235 break;
236 }
237 }
238
OnIncomingAck(QuicPacketNumber,EncryptionLevel ack_decrypted_level,const QuicAckFrame & ack_frame,QuicTime ack_receive_time,QuicPacketNumber,bool,QuicPacketNumber)239 void QuicTraceVisitor::OnIncomingAck(
240 QuicPacketNumber /*ack_packet_number*/, EncryptionLevel ack_decrypted_level,
241 const QuicAckFrame& ack_frame, QuicTime ack_receive_time,
242 QuicPacketNumber /*largest_observed*/, bool /*rtt_updated*/,
243 QuicPacketNumber /*least_unacked_sent_packet*/) {
244 quic_trace::Event* event = trace_.add_events();
245 event->set_time_us(ConvertTimestampToRecordedFormat(ack_receive_time));
246 event->set_packet_number(connection_->GetLargestReceivedPacket().ToUint64());
247 event->set_event_type(quic_trace::PACKET_RECEIVED);
248 event->set_encryption_level(EncryptionLevelToProto(ack_decrypted_level));
249
250 // TODO(vasilvv): consider removing this copy.
251 QuicAckFrame copy_of_ack = ack_frame;
252 PopulateFrameInfo(QuicFrame(©_of_ack), event->add_frames());
253 PopulateTransportState(event->mutable_transport_state());
254 }
255
OnPacketLoss(QuicPacketNumber lost_packet_number,EncryptionLevel encryption_level,TransmissionType,QuicTime detection_time)256 void QuicTraceVisitor::OnPacketLoss(QuicPacketNumber lost_packet_number,
257 EncryptionLevel encryption_level,
258 TransmissionType /*transmission_type*/,
259 QuicTime detection_time) {
260 quic_trace::Event* event = trace_.add_events();
261 event->set_time_us(ConvertTimestampToRecordedFormat(detection_time));
262 event->set_event_type(quic_trace::PACKET_LOST);
263 event->set_packet_number(lost_packet_number.ToUint64());
264 PopulateTransportState(event->mutable_transport_state());
265 event->set_encryption_level(EncryptionLevelToProto(encryption_level));
266 }
267
OnWindowUpdateFrame(const QuicWindowUpdateFrame & frame,const QuicTime & receive_time)268 void QuicTraceVisitor::OnWindowUpdateFrame(const QuicWindowUpdateFrame& frame,
269 const QuicTime& receive_time) {
270 quic_trace::Event* event = trace_.add_events();
271 event->set_time_us(ConvertTimestampToRecordedFormat(receive_time));
272 event->set_event_type(quic_trace::PACKET_RECEIVED);
273 event->set_packet_number(connection_->GetLargestReceivedPacket().ToUint64());
274
275 PopulateFrameInfo(QuicFrame(frame), event->add_frames());
276 }
277
OnSuccessfulVersionNegotiation(const ParsedQuicVersion & version)278 void QuicTraceVisitor::OnSuccessfulVersionNegotiation(
279 const ParsedQuicVersion& version) {
280 uint32_t tag =
281 quiche::QuicheEndian::HostToNet32(CreateQuicVersionLabel(version));
282 std::string binary_tag(reinterpret_cast<const char*>(&tag), sizeof(tag));
283 trace_.set_protocol_version(binary_tag);
284 }
285
OnApplicationLimited()286 void QuicTraceVisitor::OnApplicationLimited() {
287 quic_trace::Event* event = trace_.add_events();
288 event->set_time_us(
289 ConvertTimestampToRecordedFormat(connection_->clock()->ApproximateNow()));
290 event->set_event_type(quic_trace::APPLICATION_LIMITED);
291 }
292
OnAdjustNetworkParameters(QuicBandwidth bandwidth,QuicTime::Delta rtt,QuicByteCount,QuicByteCount)293 void QuicTraceVisitor::OnAdjustNetworkParameters(QuicBandwidth bandwidth,
294 QuicTime::Delta rtt,
295 QuicByteCount /*old_cwnd*/,
296 QuicByteCount /*new_cwnd*/) {
297 quic_trace::Event* event = trace_.add_events();
298 event->set_time_us(
299 ConvertTimestampToRecordedFormat(connection_->clock()->ApproximateNow()));
300 event->set_event_type(quic_trace::EXTERNAL_PARAMETERS);
301
302 quic_trace::ExternalNetworkParameters* parameters =
303 event->mutable_external_network_parameters();
304 if (!bandwidth.IsZero()) {
305 parameters->set_bandwidth_bps(bandwidth.ToBitsPerSecond());
306 }
307 if (!rtt.IsZero()) {
308 parameters->set_rtt_us(rtt.ToMicroseconds());
309 }
310 }
311
ConvertTimestampToRecordedFormat(QuicTime timestamp)312 uint64_t QuicTraceVisitor::ConvertTimestampToRecordedFormat(
313 QuicTime timestamp) {
314 if (timestamp < start_time_) {
315 QUIC_BUG(quic_bug_10284_4)
316 << "Timestamp went back in time while recording a trace";
317 return 0;
318 }
319
320 return (timestamp - start_time_).ToMicroseconds();
321 }
322
PopulateTransportState(quic_trace::TransportState * state)323 void QuicTraceVisitor::PopulateTransportState(
324 quic_trace::TransportState* state) {
325 const RttStats* rtt_stats = connection_->sent_packet_manager().GetRttStats();
326 state->set_min_rtt_us(rtt_stats->min_rtt().ToMicroseconds());
327 state->set_smoothed_rtt_us(rtt_stats->smoothed_rtt().ToMicroseconds());
328 state->set_last_rtt_us(rtt_stats->latest_rtt().ToMicroseconds());
329
330 state->set_cwnd_bytes(
331 connection_->sent_packet_manager().GetCongestionWindowInBytes());
332 QuicByteCount in_flight =
333 connection_->sent_packet_manager().GetBytesInFlight();
334 state->set_in_flight_bytes(in_flight);
335 state->set_pacing_rate_bps(connection_->sent_packet_manager()
336 .GetSendAlgorithm()
337 ->PacingRate(in_flight)
338 .ToBitsPerSecond());
339
340 if (connection_->sent_packet_manager()
341 .GetSendAlgorithm()
342 ->GetCongestionControlType() == kPCC) {
343 state->set_congestion_control_state(
344 connection_->sent_packet_manager().GetSendAlgorithm()->GetDebugState());
345 }
346 }
347
348 } // namespace quic
349