Improve debug logging and test display
gfe-relnote: n/a, debug logging and test only
PiperOrigin-RevId: 273905489
Change-Id: Iebd08a5a599fb5ff14b16f11dacdd26e0c287a64
diff --git a/quic/core/http/quic_spdy_stream.cc b/quic/core/http/quic_spdy_stream.cc
index d2e48d1..e4c209e 100644
--- a/quic/core/http/quic_spdy_stream.cc
+++ b/quic/core/http/quic_spdy_stream.cc
@@ -270,7 +270,8 @@
// layer applications.
unacked_frame_headers_offsets_.Add(0, writer.length());
- QUIC_LOG(INFO) << "Stream " << id() << " is writing type as server push";
+ QUIC_LOG(INFO) << ENDPOINT << "Stream " << id()
+ << " is writing type as server push";
WriteOrBufferData(QuicStringPiece(writer.data(), writer.length()), false,
nullptr);
}
@@ -301,14 +302,14 @@
unacked_frame_headers_offsets_.Add(
send_buffer().stream_offset(),
send_buffer().stream_offset() + header_length);
- QUIC_DLOG(INFO) << "Stream " << id()
+ QUIC_DLOG(INFO) << ENDPOINT << "Stream " << id()
<< " is writing DATA frame header of length "
<< header_length;
WriteOrBufferData(QuicStringPiece(buffer.get(), header_length), false,
nullptr);
// Write body.
- QUIC_DLOG(INFO) << "Stream " << id()
+ QUIC_DLOG(INFO) << ENDPOINT << "Stream " << id()
<< " is writing DATA frame payload of length "
<< data.length();
WriteOrBufferData(data, fin, nullptr);
@@ -327,8 +328,8 @@
// trailers may be processed out of order at the peer.
const QuicStreamOffset final_offset =
stream_bytes_written() + BufferedDataBytes();
- QUIC_DLOG(INFO) << "Inserting trailer: (" << kFinalOffsetHeaderKey << ", "
- << final_offset << ")";
+ QUIC_DLOG(INFO) << ENDPOINT << "Inserting trailer: ("
+ << kFinalOffsetHeaderKey << ", " << final_offset << ")";
trailer_block.insert(std::make_pair(
kFinalOffsetHeaderKey, QuicTextUtils::Uint64ToString(final_offset)));
}
@@ -367,7 +368,7 @@
frame.headers.length());
// Write Push Promise frame header and push id.
- QUIC_DLOG(INFO) << "Stream " << id()
+ QUIC_DLOG(INFO) << ENDPOINT << "Stream " << id()
<< " is writing Push Promise frame header of length "
<< push_promise_frame_length << " , with promised id "
<< frame.push_id;
@@ -376,7 +377,7 @@
/* fin = */ false, /* ack_listener = */ nullptr);
// Write response headers.
- QUIC_DLOG(INFO) << "Stream " << id()
+ QUIC_DLOG(INFO) << ENDPOINT << "Stream " << id()
<< " is writing Push Promise request header of length "
<< frame.headers.length();
WriteOrBufferData(frame.headers, /* fin = */ false,
@@ -417,13 +418,13 @@
unacked_frame_headers_offsets_.Add(
send_buffer().stream_offset(),
send_buffer().stream_offset() + header_length);
- QUIC_DLOG(INFO) << "Stream " << id()
+ QUIC_DLOG(INFO) << ENDPOINT << "Stream " << id()
<< " is writing DATA frame header of length "
<< header_length;
WriteMemSlices(storage.ToSpan(), false);
// Write body.
- QUIC_DLOG(INFO) << "Stream " << id()
+ QUIC_DLOG(INFO) << ENDPOINT << "Stream " << id()
<< " is writing DATA frame payload of length "
<< slices.total_length();
return WriteMemSlices(slices, fin);
@@ -611,7 +612,8 @@
// TODO(b/134706391): remove |fin| argument.
DCHECK(!trailers_decompressed_);
if (!VersionUsesQpack(transport_version()) && fin_received()) {
- QUIC_DLOG(INFO) << "Received Trailers after FIN, on stream: " << id();
+ QUIC_DLOG(INFO) << ENDPOINT
+ << "Received Trailers after FIN, on stream: " << id();
session()->connection()->CloseConnection(
QUIC_INVALID_HEADERS_STREAM_DATA, "Trailers after fin",
ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
@@ -619,7 +621,8 @@
}
if (!VersionUsesQpack(transport_version()) && !fin) {
- QUIC_DLOG(INFO) << "Trailers must have FIN set, on stream: " << id();
+ QUIC_DLOG(INFO) << ENDPOINT
+ << "Trailers must have FIN set, on stream: " << id();
session()->connection()->CloseConnection(
QUIC_INVALID_HEADERS_STREAM_DATA, "Fin missing from trailers",
ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
@@ -631,7 +634,8 @@
if (!SpdyUtils::CopyAndValidateTrailers(header_list, expect_final_byte_offset,
&final_byte_offset,
&received_trailers_)) {
- QUIC_DLOG(ERROR) << "Trailers for stream " << id() << " are malformed.";
+ QUIC_DLOG(ERROR) << ENDPOINT << "Trailers for stream " << id()
+ << " are malformed.";
session()->connection()->CloseConnection(
QUIC_INVALID_HEADERS_STREAM_DATA, "Trailers are malformed",
ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
@@ -658,7 +662,8 @@
QuicStream::OnStreamReset(frame);
return;
}
- QUIC_DVLOG(1) << "Received QUIC_STREAM_NO_ERROR, not discarding response";
+ QUIC_DVLOG(1) << ENDPOINT
+ << "Received QUIC_STREAM_NO_ERROR, not discarding response";
set_rst_received(true);
MaybeIncreaseHighestReceivedOffset(frame.byte_offset);
set_stream_error(frame.error_code);
@@ -809,7 +814,8 @@
bool QuicSpdyStream::OnDataFrameEnd() {
DCHECK(VersionHasDataFrameHeader(transport_version()));
- QUIC_DVLOG(1) << "Reaches the end of a data frame. Total bytes received are "
+ QUIC_DVLOG(1) << ENDPOINT
+ << "Reaches the end of a data frame. Total bytes received are "
<< body_manager_.total_body_bytes_received();
return true;
}
@@ -975,7 +981,7 @@
bool QuicSpdyStream::OnUnknownFrameStart(uint64_t frame_type,
QuicByteCount header_length) {
// Ignore unknown frames, but consume frame header.
- QUIC_DVLOG(1) << "Discarding " << header_length
+ QUIC_DVLOG(1) << ENDPOINT << "Discarding " << header_length
<< " byte long frame header of frame of unknown type "
<< frame_type << ".";
sequencer()->MarkConsumed(body_manager_.OnNonBody(header_length));
@@ -984,7 +990,7 @@
bool QuicSpdyStream::OnUnknownFramePayload(QuicStringPiece payload) {
// Ignore unknown frames, but consume frame payload.
- QUIC_DVLOG(1) << "Discarding " << payload.size()
+ QUIC_DVLOG(1) << ENDPOINT << "Discarding " << payload.size()
<< " bytes of payload of frame of unknown type.";
sequencer()->MarkConsumed(body_manager_.OnNonBody(payload.size()));
return true;
@@ -1045,14 +1051,14 @@
send_buffer().stream_offset(),
send_buffer().stream_offset() + headers_frame_header_length);
- QUIC_DLOG(INFO) << "Stream " << id()
+ QUIC_DLOG(INFO) << ENDPOINT << "Stream " << id()
<< " is writing HEADERS frame header of length "
<< headers_frame_header_length;
WriteOrBufferData(
QuicStringPiece(headers_frame_header.get(), headers_frame_header_length),
/* fin = */ false, /* ack_listener = */ nullptr);
- QUIC_DLOG(INFO) << "Stream " << id()
+ QUIC_DLOG(INFO) << ENDPOINT << "Stream " << id()
<< " is writing HEADERS frame payload of length "
<< encoded_headers.length();
WriteOrBufferData(encoded_headers, fin, nullptr);
diff --git a/quic/core/qpack/qpack_send_stream_test.cc b/quic/core/qpack/qpack_send_stream_test.cc
index 092aa12..82db2a5 100644
--- a/quic/core/qpack/qpack_send_stream_test.cc
+++ b/quic/core/qpack/qpack_send_stream_test.cc
@@ -33,6 +33,13 @@
Perspective perspective;
};
+// Used by ::testing::PrintToStringParamName().
+std::string PrintToString(const TestParams& tp) {
+ return QuicStrCat(
+ ParsedQuicVersionToString(tp.version), "_",
+ (tp.perspective == Perspective::IS_CLIENT ? "client" : "server"));
+}
+
std::vector<TestParams> GetTestParams() {
std::vector<TestParams> params;
ParsedQuicVersionVector all_supported_versions = AllSupportedVersions();
@@ -83,7 +90,8 @@
INSTANTIATE_TEST_SUITE_P(Tests,
QpackSendStreamTest,
- ::testing::ValuesIn(GetTestParams()));
+ ::testing::ValuesIn(GetTestParams()),
+ ::testing::PrintToStringParamName());
TEST_P(QpackSendStreamTest, WriteStreamTypeOnlyFirstTime) {
std::string data = "data";
diff --git a/quic/core/quic_session.cc b/quic/core/quic_session.cc
index f4e70d0..495d670 100644
--- a/quic/core/quic_session.cc
+++ b/quic/core/quic_session.cc
@@ -499,16 +499,16 @@
previous_bytes_written == stream->stream_bytes_written() &&
previous_fin_sent == stream->fin_sent()) {
stream->set_busy_counter(stream->busy_counter() + 1);
- QUIC_DVLOG(1) << "Suspected busy loop on stream id " << stream->id()
- << " stream_bytes_written " << stream->stream_bytes_written()
- << " fin " << stream->fin_sent() << " count "
- << stream->busy_counter();
+ QUIC_DVLOG(1) << ENDPOINT << "Suspected busy loop on stream id "
+ << stream->id() << " stream_bytes_written "
+ << stream->stream_bytes_written() << " fin "
+ << stream->fin_sent() << " count " << stream->busy_counter();
// Wait a few iterations before firing, the exact count is
// arbitrary, more than a few to cover a few test-only false
// positives.
if (stream->busy_counter() > 20) {
- QUIC_LOG(ERROR) << "Detected busy loop on stream id " << stream->id()
- << " stream_bytes_written "
+ QUIC_LOG(ERROR) << ENDPOINT << "Detected busy loop on stream id "
+ << stream->id() << " stream_bytes_written "
<< stream->stream_bytes_written() << " fin "
<< stream->fin_sent();
return false;
@@ -523,8 +523,8 @@
if (!stream->write_side_closed() && stream->HasBufferedData() &&
!stream->flow_controller()->IsBlocked() &&
!write_blocked_streams_.IsStreamBlocked(stream->id())) {
- QUIC_DLOG(ERROR) << "stream " << stream->id() << " has buffered "
- << stream->BufferedDataBytes()
+ QUIC_DLOG(ERROR) << ENDPOINT << "stream " << stream->id()
+ << " has buffered " << stream->BufferedDataBytes()
<< " bytes, and is not flow control blocked, "
"but it is not in the write block list.";
return false;
@@ -588,14 +588,17 @@
return;
}
currently_writing_stream_id_ = write_blocked_streams_.PopFront();
+ QUIC_DVLOG(1) << ENDPOINT << "Removing stream "
+ << currently_writing_stream_id_ << " from write-blocked list";
QuicStream* stream = GetOrCreateStream(currently_writing_stream_id_);
if (stream != nullptr && !stream->flow_controller()->IsBlocked()) {
// If the stream can't write all bytes it'll re-add itself to the blocked
// list.
uint64_t previous_bytes_written = stream->stream_bytes_written();
bool previous_fin_sent = stream->fin_sent();
- QUIC_DVLOG(1) << "stream " << stream->id() << " bytes_written "
- << previous_bytes_written << " fin " << previous_fin_sent;
+ QUIC_DVLOG(1) << ENDPOINT << "stream " << stream->id()
+ << " bytes_written " << previous_bytes_written << " fin "
+ << previous_fin_sent;
stream->OnCanWrite();
DCHECK(CheckStreamWriteBlocked(stream));
DCHECK(CheckStreamNotBusyLooping(stream, previous_bytes_written,
@@ -943,6 +946,7 @@
}
void QuicSession::OnConfigNegotiated() {
+ QUIC_DVLOG(1) << ENDPOINT << "OnConfigNegotiated";
connection_->SetFromConfig(config_);
if (VersionHasIetfQuicFrames(transport_version())) {
@@ -950,7 +954,8 @@
if (config_.HasReceivedMaxIncomingBidirectionalStreams()) {
max_streams = config_.ReceivedMaxIncomingBidirectionalStreams();
}
- QUIC_DVLOG(1) << "Setting Bidirectional outgoing_max_streams_ to "
+ QUIC_DVLOG(1) << ENDPOINT
+ << "Setting Bidirectional outgoing_max_streams_ to "
<< max_streams;
v99_streamid_manager_.SetMaxOpenOutgoingBidirectionalStreams(max_streams);
@@ -958,7 +963,8 @@
if (config_.HasReceivedMaxIncomingUnidirectionalStreams()) {
max_streams = config_.ReceivedMaxIncomingUnidirectionalStreams();
}
- QUIC_DVLOG(1) << "Setting Unidirectional outgoing_max_streams_ to "
+ QUIC_DVLOG(1) << ENDPOINT
+ << "Setting Unidirectional outgoing_max_streams_ to "
<< max_streams;
v99_streamid_manager_.SetMaxOpenOutgoingUnidirectionalStreams(max_streams);
} else {
@@ -966,7 +972,8 @@
if (config_.HasReceivedMaxIncomingBidirectionalStreams()) {
max_streams = config_.ReceivedMaxIncomingBidirectionalStreams();
}
- QUIC_DVLOG(1) << "Setting max_open_outgoing_streams_ to " << max_streams;
+ QUIC_DVLOG(1) << ENDPOINT << "Setting max_open_outgoing_streams_ to "
+ << max_streams;
stream_id_manager_.set_max_open_outgoing_streams(max_streams);
}
@@ -1135,6 +1142,7 @@
}
void QuicSession::OnNewStreamFlowControlWindow(QuicStreamOffset new_window) {
+ QUIC_DVLOG(1) << ENDPOINT << "OnNewStreamFlowControlWindow " << new_window;
if (new_window < kMinimumFlowControlSendWindow &&
!connection_->version().AllowsLowFlowControlLimits()) {
QUIC_LOG_FIRST_N(ERROR, 1)
@@ -1148,9 +1156,15 @@
// Inform all existing streams about the new window.
for (auto const& kv : stream_map_) {
+ QUIC_DVLOG(1) << ENDPOINT << "Informing stream " << kv.first
+ << " of new stream flow control window " << new_window;
kv.second->UpdateSendWindowOffset(new_window);
}
if (!QuicVersionUsesCryptoFrames(transport_version())) {
+ QUIC_DVLOG(1)
+ << ENDPOINT
+ << "Informing crypto stream of new stream flow control window "
+ << new_window;
GetMutableCryptoStream()->UpdateSendWindowOffset(new_window);
}
}
@@ -1218,6 +1232,7 @@
}
void QuicSession::OnNewSessionFlowControlWindow(QuicStreamOffset new_window) {
+ QUIC_DVLOG(1) << ENDPOINT << "OnNewSessionFlowControlWindow " << new_window;
if (new_window < kMinimumFlowControlSendWindow &&
!connection_->version().AllowsLowFlowControlLimits()) {
QUIC_LOG_FIRST_N(ERROR, 1)
@@ -1522,6 +1537,9 @@
QUIC_LOG_FIRST_N(ERROR, 2) << QuicStackTrace();
}
+ QUIC_DVLOG(1) << ENDPOINT << "Adding stream " << id
+ << " to write-blocked list";
+
write_blocked_streams_.AddStream(id);
}
