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);
 }
 
diff --git a/quic/tools/quic_simple_server_stream_test.cc b/quic/tools/quic_simple_server_stream_test.cc
index 533ab4e..72c3201 100644
--- a/quic/tools/quic_simple_server_stream_test.cc
+++ b/quic/tools/quic_simple_server_stream_test.cc
@@ -29,9 +29,7 @@
 using testing::AnyNumber;
 using testing::InSequence;
 using testing::Invoke;
-using testing::Return;
 using testing::StrictMock;
-using testing::ValuesIn;
 
 namespace quic {
 namespace test {
@@ -255,7 +253,8 @@
 
 INSTANTIATE_TEST_SUITE_P(Tests,
                          QuicSimpleServerStreamTest,
-                         ValuesIn(AllSupportedVersions()));
+                         ::testing::ValuesIn(AllSupportedVersions()),
+                         ::testing::PrintToStringParamName());
 
 TEST_P(QuicSimpleServerStreamTest, TestFraming) {
   EXPECT_CALL(session_, WritevData(_, _, _, _, _))