Add DV2 logs to help interop debugging
gfe-relnote: adds QUIC_DVLOG(2) logs that are not enabled in production, not flag-protected
PiperOrigin-RevId: 253144347
Change-Id: Ia632d5622aee919b9aa2a84b5bf729c8bde916d1
diff --git a/quic/core/frames/quic_frame.cc b/quic/core/frames/quic_frame.cc
index 0f3e734..b23f9c0 100644
--- a/quic/core/frames/quic_frame.cc
+++ b/quic/core/frames/quic_frame.cc
@@ -341,4 +341,12 @@
return os;
}
+std::string QuicFramesToString(const QuicFrames& frames) {
+ std::ostringstream os;
+ for (const QuicFrame& frame : frames) {
+ os << frame;
+ }
+ return os.str();
+}
+
} // namespace quic
diff --git a/quic/core/frames/quic_frame.h b/quic/core/frames/quic_frame.h
index caa5fce..1fa9e01 100644
--- a/quic/core/frames/quic_frame.h
+++ b/quic/core/frames/quic_frame.h
@@ -140,6 +140,9 @@
QUIC_EXPORT_PRIVATE QuicFrame
CopyRetransmittableControlFrame(const QuicFrame& frame);
+// Human-readable description suitable for logging.
+QUIC_EXPORT_PRIVATE std::string QuicFramesToString(const QuicFrames& frames);
+
} // namespace quic
#endif // QUICHE_QUIC_CORE_FRAMES_QUIC_FRAME_H_
diff --git a/quic/core/quic_framer.cc b/quic/core/quic_framer.cc
index d186ad3..1aec0bf 100644
--- a/quic/core/quic_framer.cc
+++ b/quic/core/quic_framer.cc
@@ -2776,6 +2776,7 @@
set_detailed_error("Packet has no frames.");
return RaiseError(QUIC_MISSING_PAYLOAD);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing packet with header " << header;
while (!reader->IsDoneReading()) {
uint8_t frame_type;
if (!reader->ReadBytes(&frame_type, 1)) {
@@ -2792,6 +2793,7 @@
if (!ProcessStreamFrame(reader, frame_type, &frame)) {
return RaiseError(QUIC_INVALID_STREAM_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing stream frame " << frame;
if (!visitor_->OnStreamFrame(frame)) {
QUIC_DVLOG(1) << ENDPOINT
<< "Visitor asked to stop further processing.";
@@ -2806,6 +2808,7 @@
if (!ProcessAckFrame(reader, frame_type)) {
return RaiseError(QUIC_INVALID_ACK_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing ACK frame";
continue;
}
@@ -2821,6 +2824,7 @@
case PADDING_FRAME: {
QuicPaddingFrame frame;
ProcessPaddingFrame(reader, &frame);
+ QUIC_DVLOG(2) << ENDPOINT << "Processing padding frame " << frame;
if (!visitor_->OnPaddingFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -2834,6 +2838,7 @@
if (!ProcessRstStreamFrame(reader, &frame)) {
return RaiseError(QUIC_INVALID_RST_STREAM_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing reset stream frame " << frame;
if (!visitor_->OnRstStreamFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -2848,6 +2853,8 @@
return RaiseError(QUIC_INVALID_CONNECTION_CLOSE_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing connection close frame "
+ << frame;
if (!visitor_->OnConnectionCloseFrame(frame)) {
QUIC_DVLOG(1) << ENDPOINT
<< "Visitor asked to stop further processing.";
@@ -2862,6 +2869,8 @@
if (!ProcessGoAwayFrame(reader, &goaway_frame)) {
return RaiseError(QUIC_INVALID_GOAWAY_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing go away frame "
+ << goaway_frame;
if (!visitor_->OnGoAwayFrame(goaway_frame)) {
QUIC_DVLOG(1) << ENDPOINT
<< "Visitor asked to stop further processing.";
@@ -2876,6 +2885,8 @@
if (!ProcessWindowUpdateFrame(reader, &window_update_frame)) {
return RaiseError(QUIC_INVALID_WINDOW_UPDATE_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing window update frame "
+ << window_update_frame;
if (!visitor_->OnWindowUpdateFrame(window_update_frame)) {
QUIC_DVLOG(1) << ENDPOINT
<< "Visitor asked to stop further processing.";
@@ -2890,6 +2901,8 @@
if (!ProcessBlockedFrame(reader, &blocked_frame)) {
return RaiseError(QUIC_INVALID_BLOCKED_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing blocked frame "
+ << blocked_frame;
if (!visitor_->OnBlockedFrame(blocked_frame)) {
QUIC_DVLOG(1) << ENDPOINT
<< "Visitor asked to stop further processing.";
@@ -2910,6 +2923,8 @@
if (!ProcessStopWaitingFrame(reader, header, &stop_waiting_frame)) {
return RaiseError(QUIC_INVALID_STOP_WAITING_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing stop waiting frame "
+ << stop_waiting_frame;
if (!visitor_->OnStopWaitingFrame(stop_waiting_frame)) {
QUIC_DVLOG(1) << ENDPOINT
<< "Visitor asked to stop further processing.";
@@ -2927,6 +2942,7 @@
// Returning true since there was no parsing error.
return true;
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing ping frame " << ping_frame;
continue;
}
case IETF_EXTENSION_MESSAGE_NO_LENGTH:
@@ -2938,6 +2954,8 @@
&message_frame)) {
return RaiseError(QUIC_INVALID_MESSAGE_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing message frame "
+ << message_frame;
if (!visitor_->OnMessageFrame(message_frame)) {
QUIC_DVLOG(1) << ENDPOINT
<< "Visitor asked to stop further processing.";
@@ -2955,6 +2973,7 @@
if (!ProcessCryptoFrame(reader, &frame)) {
return RaiseError(QUIC_INVALID_FRAME_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing crypto frame " << frame;
if (!visitor_->OnCryptoFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -2983,6 +3002,8 @@
set_detailed_error("Packet has no frames.");
return RaiseError(QUIC_MISSING_PAYLOAD);
}
+
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF packet with header " << header;
while (!reader->IsDoneReading()) {
uint64_t frame_type;
// Will be the number of bytes into which frame_type was encoded.
@@ -3008,6 +3029,7 @@
if (!ProcessIetfStreamFrame(reader, frame_type, &frame)) {
return RaiseError(QUIC_INVALID_STREAM_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF stream frame " << frame;
if (!visitor_->OnStreamFrame(frame)) {
QUIC_DVLOG(1) << ENDPOINT
<< "Visitor asked to stop further processing.";
@@ -3019,6 +3041,8 @@
case IETF_PADDING: {
QuicPaddingFrame frame;
ProcessPaddingFrame(reader, &frame);
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF padding frame "
+ << frame;
if (!visitor_->OnPaddingFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3031,6 +3055,8 @@
if (!ProcessIetfResetStreamFrame(reader, &frame)) {
return RaiseError(QUIC_INVALID_RST_STREAM_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF reset stream frame "
+ << frame;
if (!visitor_->OnRstStreamFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3049,6 +3075,8 @@
&frame)) {
return RaiseError(QUIC_INVALID_CONNECTION_CLOSE_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF connection close frame "
+ << frame;
if (!visitor_->OnConnectionCloseFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3063,6 +3091,8 @@
}
// TODO(fkastenholz): Or should we create a new visitor function,
// OnMaxDataFrame()?
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF max data frame "
+ << frame;
if (!visitor_->OnWindowUpdateFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3077,6 +3107,8 @@
}
// TODO(fkastenholz): Or should we create a new visitor function,
// OnMaxStreamDataFrame()?
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF max stream data frame "
+ << frame;
if (!visitor_->OnWindowUpdateFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3091,6 +3123,8 @@
return RaiseError(QUIC_MAX_STREAMS_DATA);
}
QUIC_CODE_COUNT_N(quic_max_streams_received, 1, 2);
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF max streams frame "
+ << frame;
if (!visitor_->OnMaxStreamsFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3101,6 +3135,8 @@
case IETF_PING: {
// Ping has no payload.
QuicPingFrame ping_frame;
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF ping frame "
+ << ping_frame;
if (!visitor_->OnPingFrame(ping_frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3113,6 +3149,8 @@
if (!ProcessIetfBlockedFrame(reader, &frame)) {
return RaiseError(QUIC_INVALID_BLOCKED_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF blocked frame "
+ << frame;
if (!visitor_->OnBlockedFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3125,6 +3163,8 @@
if (!ProcessStreamBlockedFrame(reader, &frame)) {
return RaiseError(QUIC_INVALID_STREAM_BLOCKED_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF stream blocked frame "
+ << frame;
if (!visitor_->OnBlockedFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3139,6 +3179,8 @@
return RaiseError(QUIC_STREAMS_BLOCKED_DATA);
}
QUIC_CODE_COUNT_N(quic_streams_blocked_received, 1, 2);
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF streams blocked frame "
+ << frame;
if (!visitor_->OnStreamsBlockedFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3151,6 +3193,8 @@
if (!ProcessNewConnectionIdFrame(reader, &frame)) {
return RaiseError(QUIC_INVALID_NEW_CONNECTION_ID_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT
+ << "Processing IETF new connection ID frame " << frame;
if (!visitor_->OnNewConnectionIdFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3163,6 +3207,9 @@
if (!ProcessRetireConnectionIdFrame(reader, &frame)) {
return RaiseError(QUIC_INVALID_RETIRE_CONNECTION_ID_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT
+ << "Processing IETF retire connection ID frame "
+ << frame;
if (!visitor_->OnRetireConnectionIdFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3175,6 +3222,8 @@
if (!ProcessNewTokenFrame(reader, &frame)) {
return RaiseError(QUIC_INVALID_NEW_TOKEN);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF new token frame "
+ << frame;
if (!visitor_->OnNewTokenFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3187,6 +3236,8 @@
if (!ProcessStopSendingFrame(reader, &frame)) {
return RaiseError(QUIC_INVALID_STOP_SENDING_FRAME_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF stop sending frame "
+ << frame;
if (!visitor_->OnStopSendingFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3200,6 +3251,7 @@
if (!ProcessIetfAckFrame(reader, frame_type, &frame)) {
return RaiseError(QUIC_INVALID_ACK_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF ACK frame " << frame;
break;
}
case IETF_PATH_CHALLENGE: {
@@ -3207,6 +3259,8 @@
if (!ProcessPathChallengeFrame(reader, &frame)) {
return RaiseError(QUIC_INVALID_PATH_CHALLENGE_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF path challenge frame "
+ << frame;
if (!visitor_->OnPathChallengeFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3219,6 +3273,8 @@
if (!ProcessPathResponseFrame(reader, &frame)) {
return RaiseError(QUIC_INVALID_PATH_RESPONSE_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF path response frame "
+ << frame;
if (!visitor_->OnPathResponseFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
@@ -3235,6 +3291,8 @@
&message_frame)) {
return RaiseError(QUIC_INVALID_MESSAGE_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF message frame "
+ << message_frame;
if (!visitor_->OnMessageFrame(message_frame)) {
QUIC_DVLOG(1) << ENDPOINT
<< "Visitor asked to stop further processing.";
@@ -3248,6 +3306,7 @@
if (!ProcessCryptoFrame(reader, &frame)) {
return RaiseError(QUIC_INVALID_FRAME_DATA);
}
+ QUIC_DVLOG(2) << ENDPOINT << "Processing IETF crypto frame " << frame;
if (!visitor_->OnCryptoFrame(frame)) {
QUIC_DVLOG(1) << "Visitor asked to stop further processing.";
// Returning true since there was no parsing error.
diff --git a/quic/core/quic_packet_creator.cc b/quic/core/quic_packet_creator.cc
index cc59cc7..7ba82e3 100644
--- a/quic/core/quic_packet_creator.cc
+++ b/quic/core/quic_packet_creator.cc
@@ -464,6 +464,8 @@
}
QUIC_DVLOG(1) << ENDPOINT << "Adding frame: " << frame;
+ QUIC_DVLOG(2) << ENDPOINT << "Serializing stream packet " << header << frame;
+
// TODO(ianswett): AppendTypeByte and AppendStreamFrame could be optimized
// into one method that takes a QuicStreamFrame, if warranted.
bool omit_frame_length = !needs_padding;
@@ -592,6 +594,9 @@
MaybeAddPadding();
+ QUIC_DVLOG(2) << ENDPOINT << "Serializing packet " << header
+ << QuicFramesToString(queued_frames_);
+
DCHECK_GE(max_plaintext_size_, packet_size_);
// Use the packet_size_ instead of the buffer size to ensure smaller
// packet sizes are properly used.
@@ -652,6 +657,9 @@
// FillPacketHeader increments packet_number_.
FillPacketHeader(&header);
+ QUIC_DVLOG(2) << ENDPOINT << "Serializing connectivity probing packet "
+ << header;
+
std::unique_ptr<char[]> buffer(new char[kMaxOutgoingPacketSize]);
size_t length = framer_->BuildConnectivityProbingPacket(
header, buffer.get(), max_plaintext_size_, packet_.encryption_level);
@@ -684,6 +692,8 @@
// FillPacketHeader increments packet_number_.
FillPacketHeader(&header);
+ QUIC_DVLOG(2) << ENDPOINT << "Serializing path challenge packet " << header;
+
std::unique_ptr<char[]> buffer(new char[kMaxOutgoingPacketSize]);
size_t length = framer_->BuildPaddedPathChallengePacket(
header, buffer.get(), max_plaintext_size_, payload, random_,
@@ -718,6 +728,8 @@
// FillPacketHeader increments packet_number_.
FillPacketHeader(&header);
+ QUIC_DVLOG(2) << ENDPOINT << "Serializing path response packet " << header;
+
std::unique_ptr<char[]> buffer(new char[kMaxOutgoingPacketSize]);
size_t length = framer_->BuildPathResponsePacket(
header, buffer.get(), max_plaintext_size_, payloads, is_padded,
