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); }