Improve logging in MasqueH2Connection PiperOrigin-RevId: 843816151
diff --git a/quiche/quic/masque/masque_h2_connection.cc b/quiche/quic/masque/masque_h2_connection.cc index 11bdfb1..ac6b80c 100644 --- a/quiche/quic/masque/masque_h2_connection.cc +++ b/quiche/quic/masque/masque_h2_connection.cc
@@ -27,6 +27,8 @@ #include "quiche/common/platform/api/quiche_logging.h" #include "quiche/common/quiche_text_utils.h" +#define ENDPOINT (is_server_ ? "Server: " : "Client: ") + using http2::adapter::Header; using http2::adapter::Http2KnownSettingsId; @@ -48,7 +50,7 @@ return; } aborted_ = true; - QUICHE_LOG(ERROR) << "Aborting connection"; + QUICHE_LOG(ERROR) << ENDPOINT << "Aborting connection"; visitor_->OnConnectionFinished(this); } @@ -86,7 +88,8 @@ } else { int ssl_err = SSL_get_error(ssl_, ssl_handshake_ret); if (ssl_err == SSL_ERROR_WANT_READ) { - QUICHE_DVLOG(1) << "SSL_do_handshake will require another read"; + QUICHE_DVLOG(1) << ENDPOINT + << "SSL_do_handshake will require another read"; return false; } PrintSSLError("Error while connecting", ssl_err, ssl_handshake_ret); @@ -104,11 +107,11 @@ return false; } if (ssl_read_ret == 0) { - QUICHE_LOG(INFO) << "TLS read closed"; + QUICHE_LOG(INFO) << ENDPOINT << "TLS read closed"; return false; } - QUICHE_DVLOG(1) << "Read " << ssl_read_ret << " bytes from TLS"; - QUICHE_DVLOG(2) << "Read TLS bytes:" << std::endl + QUICHE_DVLOG(1) << ENDPOINT << "Read " << ssl_read_ret << " bytes from TLS"; + QUICHE_DVLOG(2) << ENDPOINT << "Read TLS bytes:" << std::endl << quiche::QuicheTextUtils::HexDump(absl::string_view( reinterpret_cast<const char*>(buffer), ssl_read_ret)); h2_adapter_->ProcessBytes( @@ -117,7 +120,7 @@ } int MasqueH2Connection::WriteDataToTls(absl::string_view data) { - QUICHE_DVLOG(2) << "Writing " << data.size() + QUICHE_DVLOG(2) << ENDPOINT << "Writing " << data.size() << " app bytes to TLS:" << std::endl << quiche::QuicheTextUtils::HexDump(data); int ssl_write_ret = SSL_write(ssl_, data.data(), data.size()); @@ -127,17 +130,17 @@ return -1; } else { if (ssl_write_ret == static_cast<int>(data.size())) { - QUICHE_DVLOG(1) << "Wrote " << data.size() << " bytes to TLS"; + QUICHE_DVLOG(1) << ENDPOINT << "Wrote " << data.size() << " bytes to TLS"; } else { - QUICHE_DVLOG(1) << "Wrote " << ssl_write_ret << " / " << data.size() - << "bytes to TLS"; + QUICHE_DVLOG(1) << ENDPOINT << "Wrote " << ssl_write_ret << " / " + << data.size() << "bytes to TLS"; } } return ssl_write_ret; } int64_t MasqueH2Connection::OnReadyToSend(absl::string_view serialized) { - QUICHE_DVLOG(1) << "Writing " << serialized.size() + QUICHE_DVLOG(1) << ENDPOINT << "Writing " << serialized.size() << " bytes of h2 data to TLS"; int write_res = WriteDataToTls(serialized); if (write_res < 0) { @@ -185,7 +188,7 @@ } void MasqueH2Connection::OnConnectionError(ConnectionError error) { - QUICHE_LOG(ERROR) << "OnConnectionError: " + QUICHE_LOG(ERROR) << ENDPOINT << "OnConnectionError: " << http2::adapter::ConnectionErrorToString(error); Abort(); } @@ -193,7 +196,7 @@ void MasqueH2Connection::OnSettingsStart() {} void MasqueH2Connection::OnSetting(Http2Setting setting) { - QUICHE_LOG(INFO) << "Received " + QUICHE_LOG(INFO) << ENDPOINT << "Received " << http2::adapter::Http2SettingsIdToString(setting.id) << " = " << setting.value; } @@ -202,14 +205,14 @@ void MasqueH2Connection::OnSettingsAck() {} bool MasqueH2Connection::OnBeginHeadersForStream(Http2StreamId stream_id) { - QUICHE_DVLOG(1) << "OnBeginHeadersForStream " << stream_id; + QUICHE_DVLOG(1) << ENDPOINT << "OnBeginHeadersForStream " << stream_id; return true; } MasqueH2Connection::OnHeaderResult MasqueH2Connection::OnHeaderForStream( Http2StreamId stream_id, absl::string_view key, absl::string_view value) { - QUICHE_DVLOG(2) << "Stream " << stream_id << " received header " << key - << " = " << value; + QUICHE_DVLOG(2) << ENDPOINT << "Stream " << stream_id << " received header " + << key << " = " << value; GetOrCreateH2Stream(stream_id)->received_headers.AppendValueOrAddHeader( key, value); return OnHeaderResult::HEADER_OK; @@ -217,12 +220,12 @@ bool MasqueH2Connection::AttemptToSend() { if (!h2_adapter_) { - QUICHE_LOG(ERROR) << "Connection is not ready to send yet"; + QUICHE_LOG(ERROR) << ENDPOINT << "Connection is not ready to send yet"; return false; } int h2_send_result = h2_adapter_->Send(); if (h2_send_result != 0) { - QUICHE_LOG(ERROR) << "h2 adapter failed to send"; + QUICHE_LOG(ERROR) << ENDPOINT << "h2 adapter failed to send"; Abort(); return false; } @@ -231,7 +234,7 @@ bool MasqueH2Connection::OnEndHeadersForStream(Http2StreamId stream_id) { MasqueH2Stream* stream = GetOrCreateH2Stream(stream_id); - QUICHE_LOG(INFO) << "OnEndHeadersForStream " << stream_id + QUICHE_LOG(INFO) << ENDPOINT << "OnEndHeadersForStream " << stream_id << " headers: " << stream->received_headers.DebugString(); return true; } @@ -245,7 +248,8 @@ if (h2_adapter_->SubmitResponse( stream_id, h2_headers, /*end_stream=*/stream->body_to_send.empty()) != 0) { - QUICHE_LOG(ERROR) << "Failed to submit response for stream " << stream_id; + QUICHE_LOG(ERROR) << ENDPOINT << "Failed to submit response for stream " + << stream_id; Abort(); } } @@ -286,21 +290,21 @@ bool MasqueH2Connection::OnBeginDataForStream(Http2StreamId stream_id, size_t payload_length) { - QUICHE_DVLOG(1) << "OnBeginDataForStream " << stream_id + QUICHE_DVLOG(1) << ENDPOINT << "OnBeginDataForStream " << stream_id << " payload_length: " << payload_length; return true; } bool MasqueH2Connection::OnDataPaddingLength(Http2StreamId stream_id, size_t padding_length) { - QUICHE_DVLOG(1) << "OnDataPaddingLength stream_id: " << stream_id + QUICHE_DVLOG(1) << ENDPOINT << "OnDataPaddingLength stream_id: " << stream_id << " padding_length: " << padding_length; return true; } bool MasqueH2Connection::OnDataForStream(Http2StreamId stream_id, absl::string_view data) { - QUICHE_DVLOG(1) << "OnDataForStream " << stream_id + QUICHE_DVLOG(1) << ENDPOINT << "OnDataForStream " << stream_id << " data length: " << data.size(); GetOrCreateH2Stream(stream_id)->received_body.append(data); return true; @@ -308,10 +312,9 @@ bool MasqueH2Connection::OnEndStream(Http2StreamId stream_id) { MasqueH2Stream* stream = GetOrCreateH2Stream(stream_id); - QUICHE_LOG(INFO) << "Received END_STREAM for stream " << stream_id - << " body length: " << stream->received_body.size() - << std::endl - << stream->received_body; + QUICHE_LOG(INFO) << ENDPOINT << "Received END_STREAM for stream " << stream_id + << " body length: " << stream->received_body.size(); + QUICHE_DVLOG(2) << ENDPOINT << "Body: " << std::endl << stream->received_body; if (is_server_) { visitor_->OnRequest(this, stream_id, stream->received_headers, stream->received_body); @@ -324,13 +327,15 @@ void MasqueH2Connection::OnRstStream(Http2StreamId stream_id, Http2ErrorCode error_code) { - QUICHE_LOG(INFO) << "Stream " << stream_id << " reset with error code " + QUICHE_LOG(INFO) << ENDPOINT << "Stream " << stream_id + << " reset with error code " << Http2ErrorCodeToString(error_code); } bool MasqueH2Connection::OnCloseStream(Http2StreamId stream_id, Http2ErrorCode error_code) { - QUICHE_LOG(INFO) << "Stream " << stream_id << " closed with error code " + QUICHE_LOG(INFO) << ENDPOINT << "Stream " << stream_id + << " closed with error code " << Http2ErrorCodeToString(error_code); h2_streams_.erase(stream_id); return true; @@ -339,18 +344,20 @@ void MasqueH2Connection::OnPriorityForStream(Http2StreamId stream_id, Http2StreamId parent_stream_id, int weight, bool exclusive) { - QUICHE_LOG(INFO) << "Stream " << stream_id << " received priority " << weight + QUICHE_LOG(INFO) << ENDPOINT << "Stream " << stream_id + << " received priority " << weight << (exclusive ? " exclusive" : "") << " parent " << parent_stream_id; } void MasqueH2Connection::OnPing(Http2PingId ping_id, bool is_ack) { - QUICHE_LOG(INFO) << "Received ping " << ping_id << (is_ack ? " ack" : ""); + QUICHE_LOG(INFO) << ENDPOINT << "Received ping " << ping_id + << (is_ack ? " ack" : ""); } void MasqueH2Connection::OnPushPromiseForStream( Http2StreamId stream_id, Http2StreamId promised_stream_id) { - QUICHE_LOG(INFO) << "Stream " << stream_id + QUICHE_LOG(INFO) << ENDPOINT << "Stream " << stream_id << " received push promise for stream " << promised_stream_id; } @@ -358,7 +365,8 @@ bool MasqueH2Connection::OnGoAway(Http2StreamId last_accepted_stream_id, Http2ErrorCode error_code, absl::string_view opaque_data) { - QUICHE_LOG(INFO) << "Received GOAWAY frame with last_accepted_stream_id: " + QUICHE_LOG(INFO) << ENDPOINT + << "Received GOAWAY frame with last_accepted_stream_id: " << last_accepted_stream_id << " error_code: " << Http2ErrorCodeToString(error_code) << " opaque_data length: " << opaque_data.size(); @@ -367,14 +375,14 @@ void MasqueH2Connection::OnWindowUpdate(Http2StreamId stream_id, int window_increment) { - QUICHE_LOG(INFO) << "Stream " << stream_id << " received window update " - << window_increment; + QUICHE_LOG(INFO) << ENDPOINT << "Stream " << stream_id + << " received window update " << window_increment; } int MasqueH2Connection::OnBeforeFrameSent(uint8_t frame_type, Http2StreamId stream_id, size_t length, uint8_t flags) { - QUICHE_DVLOG(1) << "OnBeforeFrameSent frame_type: " + QUICHE_DVLOG(1) << ENDPOINT << "OnBeforeFrameSent frame_type: " << static_cast<int>(frame_type) << " stream_id: " << stream_id << " length: " << length << " flags: " << static_cast<int>(flags); @@ -384,7 +392,8 @@ int MasqueH2Connection::OnFrameSent(uint8_t frame_type, Http2StreamId stream_id, size_t length, uint8_t flags, uint32_t error_code) { - QUICHE_DVLOG(1) << "OnFrameSent frame_type: " << static_cast<int>(frame_type) + QUICHE_DVLOG(1) << ENDPOINT + << "OnFrameSent frame_type: " << static_cast<int>(frame_type) << " stream_id: " << stream_id << " length: " << length << " flags: " << static_cast<int>(flags) << " error_code: " << error_code; @@ -393,31 +402,33 @@ bool MasqueH2Connection::OnInvalidFrame(Http2StreamId stream_id, InvalidFrameError error) { - QUICHE_LOG(INFO) << "Stream " << stream_id << " received invalid frame error " + QUICHE_LOG(INFO) << ENDPOINT << "Stream " << stream_id + << " received invalid frame error " << http2::adapter::InvalidFrameErrorToString(error); return true; } void MasqueH2Connection::OnBeginMetadataForStream(Http2StreamId stream_id, size_t payload_length) { - QUICHE_LOG(INFO) << "Stream " << stream_id + QUICHE_LOG(INFO) << ENDPOINT << "Stream " << stream_id << " about to receive metadata of length " << payload_length; } bool MasqueH2Connection::OnMetadataForStream(Http2StreamId stream_id, absl::string_view metadata) { - QUICHE_LOG(INFO) << "Stream " << stream_id << " received metadata of length " - << metadata.size(); + QUICHE_LOG(INFO) << ENDPOINT << "Stream " << stream_id + << " received metadata of length " << metadata.size(); return true; } bool MasqueH2Connection::OnMetadataEndForStream(Http2StreamId stream_id) { - QUICHE_LOG(INFO) << "Stream " << stream_id << " done receiving metadata"; + QUICHE_LOG(INFO) << ENDPOINT << "Stream " << stream_id + << " done receiving metadata"; return true; } void MasqueH2Connection::OnErrorDebug(absl::string_view message) { - QUICHE_LOG(ERROR) << "OnErrorDebug: " << message; + QUICHE_LOG(ERROR) << ENDPOINT << "OnErrorDebug: " << message; } MasqueH2Connection::MasqueH2Stream* MasqueH2Connection::GetOrCreateH2Stream( @@ -455,3 +466,5 @@ } } // namespace quic + +#undef ENDPOINT