Improve QuicSpdySession logging Seeing the ENDPOINT in these logs makes a significant difference when debugging tests that involve both client and server. gfe-relnote: debug-only logging change PiperOrigin-RevId: 284798944 Change-Id: I2614f01a191568f3a6c43bd2ea76f7fa86b373a2
diff --git a/quic/core/http/quic_spdy_session.cc b/quic/core/http/quic_spdy_session.cc index 6680b88..661e6ef 100644 --- a/quic/core/http/quic_spdy_session.cc +++ b/quic/core/http/quic_spdy_session.cc
@@ -52,6 +52,9 @@ namespace { +#define ENDPOINT \ + (perspective() == Perspective::IS_SERVER ? "Server: " : "Client: ") + // TODO(b/124216424): remove this once HTTP/3 error codes are adopted. const uint16_t kHttpUnknownStreamType = 0x0D; @@ -464,7 +467,8 @@ ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET); return; } - QUIC_DVLOG(1) << "Received final byte offset in trailers for stream " + QUIC_DVLOG(1) << ENDPOINT + << "Received final byte offset in trailers for stream " << stream_id << ", which no longer exists."; OnFinalByteOffsetReceived(stream_id, final_byte_offset); } @@ -713,6 +717,7 @@ switch (id) { case SETTINGS_QPACK_MAX_TABLE_CAPACITY: QUIC_DVLOG(1) + << ENDPOINT << "SETTINGS_QPACK_MAX_TABLE_CAPACITY received with value " << value; // Communicate |value| to encoder, because it is used for encoding @@ -724,17 +729,19 @@ std::min(value, qpack_maximum_dynamic_table_capacity_)); break; case SETTINGS_MAX_HEADER_LIST_SIZE: - QUIC_DVLOG(1) << "SETTINGS_MAX_HEADER_LIST_SIZE received with value " + QUIC_DVLOG(1) << ENDPOINT + << "SETTINGS_MAX_HEADER_LIST_SIZE received with value " << value; max_outbound_header_list_size_ = value; break; case SETTINGS_QPACK_BLOCKED_STREAMS: - QUIC_DVLOG(1) << "SETTINGS_QPACK_BLOCKED_STREAMS received with value " + QUIC_DVLOG(1) << ENDPOINT + << "SETTINGS_QPACK_BLOCKED_STREAMS received with value " << value; qpack_encoder_->SetMaximumBlockedStreams(value); break; default: - QUIC_DVLOG(1) << "Unknown setting identifier " << id + QUIC_DVLOG(1) << ENDPOINT << "Unknown setting identifier " << id << " received with value " << value; // Ignore unknown settings. break; @@ -745,7 +752,8 @@ // SETTINGS frame received on the headers stream. switch (id) { case spdy::SETTINGS_HEADER_TABLE_SIZE: - QUIC_DVLOG(1) << "SETTINGS_HEADER_TABLE_SIZE received with value " + QUIC_DVLOG(1) << ENDPOINT + << "SETTINGS_HEADER_TABLE_SIZE received with value " << value; spdy_framer_.UpdateHeaderEncoderTableSize(value); break; @@ -753,7 +761,7 @@ if (perspective() == Perspective::IS_SERVER) { // See rfc7540, Section 6.5.2. if (value > 1) { - QUIC_DLOG(ERROR) << "Invalid value " << value + QUIC_DLOG(ERROR) << ENDPOINT << "Invalid value " << value << " received for SETTINGS_ENABLE_PUSH."; if (IsConnected()) { CloseConnectionWithDetails( @@ -762,11 +770,13 @@ } return; } - QUIC_DVLOG(1) << "SETTINGS_ENABLE_PUSH received with value " << value; + QUIC_DVLOG(1) << ENDPOINT << "SETTINGS_ENABLE_PUSH received with value " + << value; server_push_enabled_ = value; break; } else { QUIC_DLOG(ERROR) + << ENDPOINT << "Invalid SETTINGS_ENABLE_PUSH received by client with value " << value; if (IsConnected()) { @@ -779,11 +789,12 @@ // TODO(fayang): Need to support SETTINGS_MAX_HEADER_LIST_SIZE when // clients are actually sending it. case spdy::SETTINGS_MAX_HEADER_LIST_SIZE: - QUIC_DVLOG(1) << "SETTINGS_MAX_HEADER_LIST_SIZE received with value " + QUIC_DVLOG(1) << ENDPOINT + << "SETTINGS_MAX_HEADER_LIST_SIZE received with value " << value; break; default: - QUIC_DLOG(ERROR) << "Unknown setting identifier " << id + QUIC_DLOG(ERROR) << ENDPOINT << "Unknown setting identifier " << id << " received with value " << value; if (IsConnected()) { CloseConnectionWithDetails( @@ -844,8 +855,8 @@ } void QuicSpdySession::OnHeaderList(const QuicHeaderList& header_list) { - QUIC_DVLOG(1) << "Received header list for stream " << stream_id_ << ": " - << header_list.DebugString(); + QUIC_DVLOG(1) << ENDPOINT << "Received header list for stream " << stream_id_ + << ": " << header_list.DebugString(); // This code path is only executed for push promise in IETF QUIC. if (VersionUsesHttp3(transport_version())) { DCHECK(promised_stream_id_ != @@ -930,7 +941,7 @@ receive_control_stream_ = receive_stream.get(); ActivateStream(std::move(receive_stream)); receive_control_stream_->SetUnblocked(); - QUIC_DVLOG(1) << "Receive Control stream is created"; + QUIC_DVLOG(1) << ENDPOINT << "Receive Control stream is created"; if (debug_visitor_ != nullptr) { debug_visitor_->OnPeerControlStreamCreated( receive_control_stream_->id()); @@ -952,7 +963,7 @@ qpack_encoder_receive_stream_ = encoder_receive.get(); ActivateStream(std::move(encoder_receive)); qpack_encoder_receive_stream_->SetUnblocked(); - QUIC_DVLOG(1) << "Receive QPACK Encoder stream is created"; + QUIC_DVLOG(1) << ENDPOINT << "Receive QPACK Encoder stream is created"; if (debug_visitor_ != nullptr) { debug_visitor_->OnPeerQpackEncoderStreamCreated( qpack_encoder_receive_stream_->id()); @@ -969,7 +980,7 @@ qpack_decoder_receive_stream_ = decoder_receive.get(); ActivateStream(std::move(decoder_receive)); qpack_decoder_receive_stream_->SetUnblocked(); - QUIC_DVLOG(1) << "Receive QPACK Decoder stream is created"; + QUIC_DVLOG(1) << ENDPOINT << "Receive QPACK Decoder stream is created"; if (debug_visitor_ != nullptr) { debug_visitor_->OnPeerQpackDecoderStreamCreated( qpack_decoder_receive_stream_->id()); @@ -1028,7 +1039,8 @@ QuicStreamId old_max_allowed_push_id = max_allowed_push_id_; max_allowed_push_id_ = max_allowed_push_id; - QUIC_DVLOG(1) << "Setting max_allowed_push_id to: " << max_allowed_push_id_ + QUIC_DVLOG(1) << ENDPOINT + << "Setting max_allowed_push_id to: " << max_allowed_push_id_ << " from: " << old_max_allowed_push_id; if (perspective() == Perspective::IS_SERVER) { @@ -1104,4 +1116,6 @@ } } +#undef ENDPOINT // undef for jumbo builds + } // namespace quic