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,