Log probe numbers in OHTTP test client This will make prober failures much easier to debug since multiple probes happen concurrently in the same process. PiperOrigin-RevId: 918653384
diff --git a/quiche/quic/masque/masque_connection_pool.cc b/quiche/quic/masque/masque_connection_pool.cc index 24e86d1..08b237e 100644 --- a/quiche/quic/masque/masque_connection_pool.cc +++ b/quiche/quic/masque/masque_connection_pool.cc
@@ -36,6 +36,8 @@ #include "quiche/common/quiche_socket_address.h" #include "quiche/common/quiche_status_utils.h" +#define ENDPOINT info_ << ": " + namespace quic { namespace { @@ -144,12 +146,13 @@ MasqueConnectionPool::MasqueConnectionPool( QuicEventLoop* event_loop, SSL_CTX* ssl_ctx, bool disable_certificate_verification, const DnsConfig& dns_config, - Visitor* visitor) + Visitor* visitor, absl::string_view info_string) : event_loop_(event_loop), tls_ssl_ctx_(ssl_ctx), disable_certificate_verification_(disable_certificate_verification), dns_config_(dns_config), - visitor_(visitor) {} + visitor_(visitor), + info_(info_string) {} void MasqueConnectionPool::OnConnectionReady(MasqueH2Connection* connection) { SendPendingRequests(connection); @@ -168,7 +171,7 @@ int32_t /*stream_id*/, const quiche::HttpHeaderBlock& /*headers*/, const std::string& /*body*/) { - QUICHE_LOG(FATAL) << "Client cannot receive requests"; + QUICHE_LOG(FATAL) << ENDPOINT << "Client cannot receive requests"; } void MasqueConnectionPool::OnResponse(MasqueH2Connection* connection, @@ -199,7 +202,8 @@ ++it; } if (!found) { - QUICHE_LOG(ERROR) << "Received unexpected response for unknown request: " + QUICHE_LOG(ERROR) << ENDPOINT + << "Received unexpected response for unknown request: " << headers.DebugString(); } } @@ -254,7 +258,7 @@ GetOrCreateConnectionState(std::string(authority->second), mtls)); auto pending_request = std::make_unique<PendingRequest>(); if (connection->connection() != nullptr) { - QUICHE_LOG(INFO) << "Reusing existing connection " + QUICHE_LOG(INFO) << ENDPOINT << "Reusing existing connection " << connection->connection()->info() << " to " << authority->second; pending_request->connection = connection->connection(); @@ -266,7 +270,8 @@ } connection->connection()->AttemptToSend(); } else { - QUICHE_LOG(INFO) << "No existing connection to " << authority->second; + QUICHE_LOG(INFO) << ENDPOINT << "No existing connection to " + << authority->second; } RequestId request_id = ++next_request_id_; pending_request->request.headers = request.headers.Clone(); @@ -330,14 +335,15 @@ PendingRequest& pending_request = *it->second; auto authority_header = pending_request.request.headers.find(":authority"); if (authority_header == pending_request.request.headers.end()) { - QUICHE_LOG(ERROR) << "Request missing :authority header"; + QUICHE_LOG(ERROR) << ENDPOINT << "Request missing :authority header"; continue; } if (authority_header->second != authority) { continue; } - QUICHE_LOG(INFO) << "Attaching connection " << connection->info() - << " to pending request for " << authority; + QUICHE_LOG(INFO) << ENDPOINT << "Attaching connection " + << connection->info() << " to pending request for " + << authority; pending_request.connection = connection; } } @@ -352,13 +358,14 @@ } bool is_request_complete = pending_request.pending_data.empty() && pending_request.end_stream_pending; - QUICHE_LOG(INFO) << "Sending pending request ID " << request_id; + QUICHE_LOG(INFO) << ENDPOINT << "Sending pending request ID " << request_id; int32_t stream_id = connection->SendRequest( pending_request.request.headers, pending_request.request.body, is_request_complete, pending_request.stream_response); if (stream_id < 0) { - QUICHE_LOG(ERROR) << "Failed to send request ID " << request_id - << " on connection " << connection->info(); + QUICHE_LOG(ERROR) << ENDPOINT << "Failed to send request ID " + << request_id << " on connection " + << connection->info(); visitor_->OnPoolResponse(this, request_id, absl::InternalError("Failed to send request"), /*end_stream=*/true); @@ -397,15 +404,15 @@ MasqueConnectionPool::ConnectionState::ConnectionState( MasqueConnectionPool* connection_pool) - : connection_pool_(connection_pool) {} + : connection_pool_(connection_pool), info_(connection_pool->info()) {} MasqueConnectionPool::ConnectionState::~ConnectionState() { if (socket_ != kInvalidSocketFd) { if (!connection_pool_->event_loop()->UnregisterSocket(socket_)) { - QUICHE_LOG(ERROR) << "Failed to unregister socket"; + QUICHE_LOG(ERROR) << ENDPOINT << "Failed to unregister socket"; } if (!socket_api::Close(socket_).ok()) { - QUICHE_LOG(ERROR) << "Error while closing socket"; + QUICHE_LOG(ERROR) << ENDPOINT << "Error while closing socket"; } socket_ = kInvalidSocketFd; } @@ -444,15 +451,16 @@ socket_, kSocketEventReadable | kSocketEventWritable, this)) { return absl::InternalError("Failed to register socket with the event loop"); } - QUICHE_LOG(INFO) << "Socket fd " << socket_ << " connect in progress to " - << socket_address; + QUICHE_LOG(INFO) << ENDPOINT << "Socket fd " << socket_ + << " connect in progress to " << socket_address; if (disable_certificate_verification) { proof_verifier_ = std::make_unique<FakeProofVerifier>(); } else { proof_verifier_ = CreateDefaultProofVerifier(host_); if (!proof_verifier_) { - QUICHE_LOG(FATAL) << "The default proof verifier is not supported. Pass " + QUICHE_LOG(FATAL) << ENDPOINT + << "The default proof verifier is not supported. Pass " "in --disable_certificate_verification."; } } @@ -466,7 +474,7 @@ (!connection_ || !connection_->aborted())) { if (!event_loop->RearmSocket( fd, kSocketEventReadable | kSocketEventWritable)) { - QUICHE_LOG(FATAL) << "Failed to re-arm socket " << fd; + QUICHE_LOG(FATAL) << ENDPOINT << "Failed to re-arm socket " << fd; } } }); @@ -483,12 +491,12 @@ SSL_set_connect_state(ssl_.get()); if (SSL_set_app_data(ssl_.get(), this) != 1) { - QUICHE_LOG(FATAL) << "SSL_set_app_data failed"; + QUICHE_LOG(FATAL) << ENDPOINT << "SSL_set_app_data failed"; } SSL_set_custom_verify(ssl_.get(), SSL_VERIFY_PEER, &VerifyCallback); if (SSL_set_tlsext_host_name(ssl_.get(), host_.c_str()) != 1) { - QUICHE_LOG(FATAL) << "SSL_set_tlsext_host_name failed"; + QUICHE_LOG(FATAL) << ENDPOINT << "SSL_set_tlsext_host_name failed"; } static constexpr uint8_t kAlpnProtocols[] = { @@ -498,13 +506,14 @@ }; if (SSL_set_alpn_protos(ssl_.get(), kAlpnProtocols, sizeof(kAlpnProtocols)) != 0) { - QUICHE_LOG(FATAL) << "SSL_set_alpn_protos failed"; + QUICHE_LOG(FATAL) << ENDPOINT << "SSL_set_alpn_protos failed"; } BIO* bio = BIO_new_socket(socket_, BIO_CLOSE); SSL_set_bio(ssl_.get(), bio, bio); // `SSL_set_bio` causes `ssl_` to take ownership of `bio`. connection_ = std::make_unique<MasqueH2Connection>( - ssl_.get(), /*is_server=*/false, connection_pool_); + ssl_.get(), /*is_server=*/false, connection_pool_, + connection_pool_->info()); connection_pool_->AttachConnectionToPendingRequests(authority_, connection_.get()); connection_->OnTransportReadable(); @@ -526,7 +535,7 @@ uint8_t* out_alert) { const STACK_OF(CRYPTO_BUFFER)* cert_chain = SSL_get0_peer_certificates(ssl); if (cert_chain == nullptr) { - QUICHE_LOG(ERROR) << "No certificate chain"; + QUICHE_LOG(ERROR) << ENDPOINT << "No certificate chain"; *out_alert = SSL_AD_INTERNAL_ERROR; return ssl_verify_invalid; } @@ -554,12 +563,12 @@ /*callback=*/nullptr); if (verify_status != QUIC_SUCCESS) { // TODO(dschinazi) properly handle QUIC_PENDING. - QUICHE_LOG(ERROR) << "Failed to verify certificate" + QUICHE_LOG(ERROR) << ENDPOINT << "Failed to verify certificate" << (verify_status == QUIC_PENDING ? " (pending)" : "") << ": " << error_details; return ssl_verify_invalid; } - QUICHE_LOG(INFO) << "Successfully verified certificate"; + QUICHE_LOG(INFO) << ENDPOINT << "Successfully verified certificate"; return ssl_verify_ok; } @@ -633,3 +642,5 @@ } } // namespace quic + +#undef ENDPOINT
diff --git a/quiche/quic/masque/masque_connection_pool.h b/quiche/quic/masque/masque_connection_pool.h index 0c89733..764f72f 100644 --- a/quiche/quic/masque/masque_connection_pool.h +++ b/quiche/quic/masque/masque_connection_pool.h
@@ -100,7 +100,8 @@ // `event_loop`, `ssl_ctx`, and `visitor` must outlive this object. explicit MasqueConnectionPool(QuicEventLoop* event_loop, SSL_CTX* ssl_ctx, bool disable_certificate_verification, - const DnsConfig& dns_config, Visitor* visitor); + const DnsConfig& dns_config, Visitor* visitor, + absl::string_view info_string); QuicEventLoop* event_loop() { return event_loop_; } SSL_CTX* GetSslCtx(bool mtls) { return mtls ? mtls_ssl_ctx_ : tls_ssl_ctx_; } @@ -129,6 +130,8 @@ const std::string& client_cert_pem_data, const std::string& client_cert_key_data); + const std::string& info() const { return info_; } + private: class ConnectionState : public QuicSocketEventListener { public: @@ -155,6 +158,7 @@ bssl::UniquePtr<SSL> ssl_; std::unique_ptr<MasqueH2Connection> connection_; bool mtls_ = false; + const std::string info_; }; struct PendingRequest { Message request; @@ -187,6 +191,7 @@ absl::flat_hash_map<RequestId, std::unique_ptr<PendingRequest>> pending_requests_; RequestId next_request_id_ = 0; + const std::string info_; }; } // namespace quic
diff --git a/quiche/quic/masque/masque_h2_connection.cc b/quiche/quic/masque/masque_h2_connection.cc index 7ead699..c856a56 100644 --- a/quiche/quic/masque/masque_h2_connection.cc +++ b/quiche/quic/masque/masque_h2_connection.cc
@@ -83,10 +83,12 @@ } MasqueH2Connection::MasqueH2Connection(SSL* ssl, bool is_server, - Visitor* visitor) + Visitor* visitor, + absl::string_view info_string) : ssl_(ssl), is_server_(is_server), - info_(absl::StrCat(is_server ? "S" : "C", GetNextConnectionId())), + info_(absl::StrCat(info_string, "-", is_server ? "S" : "C", + GetNextConnectionId())), visitor_(visitor) {} void MasqueH2Connection::OnTransportReadable() {
diff --git a/quiche/quic/masque/masque_h2_connection.h b/quiche/quic/masque/masque_h2_connection.h index 4058e9c..ee9fe95 100644 --- a/quiche/quic/masque/masque_h2_connection.h +++ b/quiche/quic/masque/masque_h2_connection.h
@@ -55,7 +55,8 @@ }; // `ssl` and `visitor` must outlive this object. - explicit MasqueH2Connection(SSL* ssl, bool is_server, Visitor* visitor); + explicit MasqueH2Connection(SSL* ssl, bool is_server, Visitor* visitor, + absl::string_view info_string); MasqueH2Connection(const MasqueH2Connection&) = delete; MasqueH2Connection(MasqueH2Connection&&) = delete;
diff --git a/quiche/quic/masque/masque_ohttp_client.cc b/quiche/quic/masque/masque_ohttp_client.cc index 7687e29..0f2b5d4 100644 --- a/quiche/quic/masque/masque_ohttp_client.cc +++ b/quiche/quic/masque/masque_ohttp_client.cc
@@ -45,6 +45,8 @@ #include "quiche/oblivious_http/oblivious_http_client.h" #include <zlib.h> +#define ENDPOINT info_ << ": " + namespace quic { using ::quic::MasqueConnectionPool; @@ -106,26 +108,27 @@ class PingPongResponseVisitor : public MasqueOhttpClient::ResponseVisitor { public: - explicit PingPongResponseVisitor(std::vector<std::string> chunks) - : chunks_(std::move(chunks)) {} + explicit PingPongResponseVisitor(std::vector<std::string> chunks, + absl::string_view info_string) + : chunks_(std::move(chunks)), info_(info_string) {} void OnRequestStarted(quic::MasqueConnectionPool::RequestId request_id, MasqueOhttpClient* client) override { - QUICHE_LOG(INFO) << "Ping-pong request " << request_id << " started with " - << chunks_.size() << " chunks"; + QUICHE_LOG(INFO) << ENDPOINT << "Ping-pong request " << request_id + << " started with " << chunks_.size() << " chunks"; request_id_ = request_id; client_ = client; bool is_final = (chunks_.size() <= 1); status_ = client_->SendBodyChunk(request_id_, chunks_[0], is_final); if (!status_.ok()) { - QUICHE_LOG(ERROR) << "Ping-pong request " << request_id + QUICHE_LOG(ERROR) << ENDPOINT << "Ping-pong request " << request_id << " failed to send first chunk: " << status_.message(); done_ = true; return; } current_chunk_idx_ = 1; if (is_final) { - QUICHE_LOG(INFO) << "Ping-pong request " << request_id + QUICHE_LOG(INFO) << ENDPOINT << "Ping-pong request " << request_id << " only had one chunk, marking as done"; done_ = true; } @@ -143,7 +146,7 @@ status_ = client_->SendBodyChunk(request_id_, chunks_[current_chunk_idx_], is_final); if (!status_.ok()) { - QUICHE_LOG(ERROR) << "Ping-pong request " << request_id + QUICHE_LOG(ERROR) << ENDPOINT << "Ping-pong request " << request_id << " failed to send chunk #" << current_chunk_idx_ << ": " << status_.message(); done_ = true; @@ -154,7 +157,7 @@ void OnResponseDone(quic::MasqueConnectionPool::RequestId request_id, const MasqueOhttpClient::Message&) override { - QUICHE_LOG(INFO) << "Ping-pong request done: " << request_id; + QUICHE_LOG(INFO) << ENDPOINT << "Ping-pong request done: " << request_id; if (request_id == request_id_) { done_ = true; } @@ -162,7 +165,7 @@ void OnError(quic::MasqueConnectionPool::RequestId request_id, absl::Status status) override { - QUICHE_LOG(ERROR) << "Ping-pong request " << request_id + QUICHE_LOG(ERROR) << ENDPOINT << "Ping-pong request " << request_id << " got error: " << status.message(); if (request_id == request_id_) { status_ = status; @@ -180,10 +183,12 @@ quic::MasqueConnectionPool::RequestId request_id_ = 0; bool done_ = false; absl::Status status_ = absl::OkStatus(); + const std::string info_; }; absl::StatusOr<std::unique_ptr<PingPongResponseVisitor>> -CreateVisitorIfPingPong(const MasqueOhttpClient::Config& config) { +CreateVisitorIfPingPong(const MasqueOhttpClient::Config& config, + absl::string_view info_string) { const MasqueOhttpClient::Config::PerRequestConfig* ping_pong_config = nullptr; for (const auto& req_config : config.per_request_configs()) { @@ -219,7 +224,8 @@ string_chunks.push_back(std::string(chunk)); } - return std::make_unique<PingPongResponseVisitor>(std::move(string_chunks)); + return std::make_unique<PingPongResponseVisitor>(std::move(string_chunks), + info_string); } } // namespace @@ -390,16 +396,19 @@ } MasqueOhttpClient::MasqueOhttpClient(Config config, - quic::QuicEventLoop* event_loop) + quic::QuicEventLoop* event_loop, + absl::string_view info_string) : config_(std::move(config)), + info_(info_string), connection_pool_(event_loop, config_.key_fetch_ssl_ctx(), config_.disable_certificate_verification(), - config_.dns_config(), this) { + config_.dns_config(), this, info_) { connection_pool_.SetMtlsSslCtx(config_.ohttp_ssl_ctx()); } // static -absl::Status MasqueOhttpClient::Run(Config config) { +absl::Status MasqueOhttpClient::Run(Config config, + absl::string_view info_string) { if (config.per_request_configs().empty()) { return absl::InvalidArgumentError("No OHTTP URLs to request"); } @@ -411,13 +420,13 @@ } QUICHE_ASSIGN_OR_RETURN( std::unique_ptr<PingPongResponseVisitor> ping_pong_visitor, - CreateVisitorIfPingPong(config)); + CreateVisitorIfPingPong(config, info_string)); quiche::QuicheSystemEventLoop system_event_loop("masque_ohttp_client"); std::unique_ptr<QuicEventLoop> event_loop = GetDefaultEventLoop()->Create(QuicDefaultClock::Get()); - MasqueOhttpClient ohttp_client(std::move(config), event_loop.get()); - + MasqueOhttpClient ohttp_client(std::move(config), event_loop.get(), + info_string); if (ping_pong_visitor) { ohttp_client.set_response_visitor(ping_pong_visitor.get()); } @@ -457,12 +466,13 @@ QUICHE_CHECK(!status.ok()); if (!status_.ok()) { QUICHE_LOG(ERROR) - << "MasqueOhttpClient already aborted, ignoring new error: " + << ENDPOINT << "MasqueOhttpClient already aborted, ignoring new error: " << status.message(); return; } status_ = status; - QUICHE_LOG(ERROR) << "Aborting MasqueOhttpClient: " << status_.message(); + QUICHE_LOG(ERROR) << ENDPOINT + << "Aborting MasqueOhttpClient: " << status_.message(); } absl::StatusOr<QuicUrl> ParseUrl(const std::string& url_string) { @@ -569,7 +579,7 @@ return absl::FailedPreconditionError(absl::StrCat( "Failed to fetch OHTTP keys: ", response.status().message())); } - QUICHE_LOG(INFO) << "Received OHTTP keys response: " + QUICHE_LOG(INFO) << ENDPOINT << "Received OHTTP keys response: " << response->headers.DebugString(); QUICHE_RETURN_IF_ERROR(CheckStatusAndContentType( *response, "application/ohttp-keys", std::nullopt)); @@ -584,7 +594,7 @@ return absl::FailedPreconditionError(absl::StrCat( "Failed to parse OHTTP keys: ", key_configs.status().message())); } - QUICHE_LOG(INFO) << "Successfully got " << key_configs->NumKeys() + QUICHE_LOG(INFO) << ENDPOINT << "Successfully got " << key_configs->NumKeys() << " OHTTP keys: " << std::endl << key_configs->DebugString(); if (config_.per_request_configs().empty()) { @@ -595,7 +605,7 @@ !absl::StrContains(config_.relay_url(), "://")) { relay_url_ = QuicUrl(absl::StrCat("https://", config_.relay_url())); } - QUICHE_LOG(INFO) << "Using relay URL: " << relay_url_.ToString(); + QUICHE_LOG(INFO) << ENDPOINT << "Using relay URL: " << relay_url_.ToString(); ObliviousHttpHeaderKeyConfig key_config = key_configs->PreferredConfig(); absl::StatusOr<absl::string_view> public_key = key_configs->GetPublicKeyForId(key_config.GetKeyId()); @@ -640,7 +650,8 @@ std::string encrypted_data; PendingRequest pending_request(per_request_config); if (!ohttp_client_.has_value()) { - QUICHE_LOG(FATAL) << "Cannot send OHTTP request without OHTTP client"; + QUICHE_LOG(FATAL) << ENDPOINT + << "Cannot send OHTTP request without OHTTP client"; return absl::InternalError( "Cannot send OHTTP request without OHTTP client"); } @@ -700,7 +711,7 @@ int num_ohttp_chunks = per_request_config.num_ohttp_chunks(); if (num_ohttp_chunks > 0) { pending_request.chunk_handler = - std::make_unique<ChunkHandler>(config_.handle_gzip_response()); + std::make_unique<ChunkHandler>(config_.handle_gzip_response(), info_); QUICHE_ASSIGN_OR_RETURN( ChunkedObliviousHttpClient chunked_client, ChunkedObliviousHttpClient::Create( @@ -750,7 +761,8 @@ request_id.status().message())); } - QUICHE_LOG(INFO) << "Sent OHTTP request for " << per_request_config.url(); + QUICHE_LOG(INFO) << ENDPOINT << "Sent OHTTP request for " + << per_request_config.url(); if (pending_request.chunk_handler) { pending_request.chunk_handler->SetResponseChunkCallback( @@ -779,7 +791,7 @@ QUICHE_ASSIGN_OR_RETURN( ObliviousHttpResponse ohttp_response, ohttp_client_->DecryptObliviousHttpResponse(response.body, context)); - QUICHE_LOG(INFO) << "Received OHTTP response for " << request_id; + QUICHE_LOG(INFO) << ENDPOINT << "Received OHTTP response for " << request_id; QUICHE_VLOG(2) << "Decrypted unchunked response body: " << absl::BytesToHexString(ohttp_response.GetPlaintextData()); quiche::QuicheDataReader reader(ohttp_response.GetPlaintextData()); @@ -802,7 +814,7 @@ encapsulated_response.body = binary_response->body(); return encapsulated_response; } - ChunkHandler chunk_handler(config_.handle_gzip_response()); + ChunkHandler chunk_handler(config_.handle_gzip_response(), info_); chunk_handler.SetResponseChunkCallback( [this, request_id](absl::string_view chunk) { if (response_visitor_) { @@ -867,10 +879,12 @@ expected_gateway_status_code); if (!status.ok()) { if (!response->body.empty()) { - QUICHE_LOG(ERROR) << "Bad " << content_type << " with body:" << std::endl + QUICHE_LOG(ERROR) << ENDPOINT << "Bad " << content_type + << " with body:" << std::endl << response->body; } else { - QUICHE_LOG(ERROR) << "Bad " << content_type << " with empty body"; + QUICHE_LOG(ERROR) << ENDPOINT << "Bad " << content_type + << " with empty body"; } return status; } @@ -884,7 +898,8 @@ if (!end_stream) { // We delivered headers. For chunked OHTTP, we just wait for data chunks. if (it->second.per_request_config.num_ohttp_chunks() <= 0) { - QUICHE_LOG(ERROR) << "Received partial response for non-chunked OHTTP"; + QUICHE_LOG(ERROR) << ENDPOINT + << "Received partial response for non-chunked OHTTP"; return absl::InternalError( "Received partial response for non-chunked OHTTP"); } @@ -912,7 +927,8 @@ TryExtractEncapsulatedResponse( request_id, *it->second.context, *response)); } - QUICHE_LOG(INFO) << "Successfully decapsulated response for request ID " + QUICHE_LOG(INFO) << ENDPOINT + << "Successfully decapsulated response for request ID " << request_id << ". Body length is " << encapsulated_response->body.size() << ". Headers:" << encapsulated_response->headers.DebugString(); @@ -924,7 +940,8 @@ size_t compressed_size = encapsulated_response->body.size(); QUICHE_ASSIGN_OR_RETURN(std::string decompressed_body, GzipDecompress(encapsulated_response->body)); - QUICHE_LOG(INFO) << "Successfully decompressed gzip response from size " + QUICHE_LOG(INFO) << ENDPOINT + << "Successfully decompressed gzip response from size " << compressed_size << " to size " << decompressed_body.size(); encapsulated_response->body = std::move(decompressed_body); @@ -1098,8 +1115,9 @@ absl::Status MasqueOhttpClient::ChunkHandler::OnDecryptedChunk( absl::string_view decrypted_chunk) { decrypted_chunk_count_++; - QUICHE_LOG(INFO) << "Received decrypted chunk #" << decrypted_chunk_count_ - << " of size " << decrypted_chunk.size(); + QUICHE_LOG(INFO) << ENDPOINT << "Received decrypted chunk #" + << decrypted_chunk_count_ << " of size " + << decrypted_chunk.size(); absl::StrAppend(&buffered_binary_response_, decrypted_chunk); if (!is_chunked_response_.has_value()) { quiche::QuicheDataReader reader(buffered_binary_response_); @@ -1167,7 +1185,8 @@ return absl::OkStatus(); } absl::Status MasqueOhttpClient::ChunkHandler::OnFinalResponseHeadersDone() { - QUICHE_LOG(INFO) << "Received incremental OHTTP response headers: " + QUICHE_LOG(INFO) << ENDPOINT + << "Received incremental OHTTP response headers: " << response_.headers.DebugString(); if (handle_gzip_response_) { auto it = response_.headers.find("content-encoding"); @@ -1181,7 +1200,7 @@ absl::Status MasqueOhttpClient::ChunkHandler::OnBodyChunk( absl::string_view body_chunk) { body_chunk_count_++; - QUICHE_LOG(INFO) << "Received body chunk #" << body_chunk_count_ + QUICHE_LOG(INFO) << ENDPOINT << "Received body chunk #" << body_chunk_count_ << " of size " << body_chunk.size(); if (body_chunk.empty()) { @@ -1198,7 +1217,8 @@ decompressed, decompressor_->Decompress(body_chunk, /*end_stream=*/false)); processed_chunk = decompressed; - QUICHE_LOG(INFO) << "Decompressed chunk to size " << processed_chunk.size(); + QUICHE_LOG(INFO) << ENDPOINT << "Decompressed chunk to size " + << processed_chunk.size(); if (processed_chunk.empty()) { return absl::OkStatus(); } @@ -1231,3 +1251,5 @@ } } // namespace quic + +#undef ENDPOINT
diff --git a/quiche/quic/masque/masque_ohttp_client.h b/quiche/quic/masque/masque_ohttp_client.h index cba9716..b497ad6 100644 --- a/quiche/quic/masque/masque_ohttp_client.h +++ b/quiche/quic/masque/masque_ohttp_client.h
@@ -246,7 +246,7 @@ // Starts by fetching the HPKE keys and then runs the client until all // requests are complete or aborted. - static absl::Status Run(Config config); + static absl::Status Run(Config config, absl::string_view info_string); // Sends a body chunk for a chunked OHTTP request. absl::Status SendBodyChunk(RequestId request_id, absl::string_view chunk, @@ -259,6 +259,8 @@ void OnPoolData(quic::MasqueConnectionPool* /*pool*/, RequestId request_id, absl::string_view data, bool end_stream) override; + const std::string& info() const { return info_; } + private: // Fetch key from the key URL. absl::Status StartKeyFetch(const std::string& url_string); @@ -283,8 +285,11 @@ public: using ResponseChunkCallback = std::function<void(absl::string_view)>; - explicit ChunkHandler(bool handle_gzip_response) - : decoder_(this), handle_gzip_response_(handle_gzip_response) {} + explicit ChunkHandler(bool handle_gzip_response, + absl::string_view info_string) + : decoder_(this), + handle_gzip_response_(handle_gzip_response), + info_(info_string) {} void SetResponseChunkCallback(ResponseChunkCallback callback) { response_chunk_callback_ = std::move(callback); } @@ -343,6 +348,7 @@ bool handle_gzip_response_ = false; bool is_gzipped_ = false; std::unique_ptr<GzipDecompressor> decompressor_; + const std::string info_; }; struct PendingRequest { @@ -360,7 +366,8 @@ encoder; }; - explicit MasqueOhttpClient(Config config, quic::QuicEventLoop* event_loop); + explicit MasqueOhttpClient(Config config, quic::QuicEventLoop* event_loop, + absl::string_view info_string); // Starts fetching for the key and sends the OHTTP request. absl::Status Start(); @@ -379,6 +386,7 @@ std::optional<uint16_t> expected_status_code); Config config_; + const std::string info_; quic::MasqueConnectionPool connection_pool_; std::optional<RequestId> key_fetch_request_id_; absl::Status status_ = absl::OkStatus();
diff --git a/quiche/quic/masque/masque_ohttp_client_bin.cc b/quiche/quic/masque/masque_ohttp_client_bin.cc index 4cf330e..4047040 100644 --- a/quiche/quic/masque/masque_ohttp_client_bin.cc +++ b/quiche/quic/masque/masque_ohttp_client_bin.cc
@@ -254,7 +254,7 @@ } config.AddPerRequestConfig(per_request_config); } - return MasqueOhttpClient::Run(std::move(config)); + return MasqueOhttpClient::Run(std::move(config), "OC"); } } // namespace
diff --git a/quiche/quic/masque/masque_tcp_client_bin.cc b/quiche/quic/masque/masque_tcp_client_bin.cc index 97a1ee4..828d442 100644 --- a/quiche/quic/masque/masque_tcp_client_bin.cc +++ b/quiche/quic/masque/masque_tcp_client_bin.cc
@@ -537,7 +537,7 @@ void SendH2Request() { h2_connection_ = std::make_unique<MasqueH2Connection>(ssl_.get(), - /*is_server=*/false, this); + /*is_server=*/false, this, "TC"); h2_connection_->OnTransportReadable(); quiche::HttpHeaderBlock headers; headers[":method"] = "GET";
diff --git a/quiche/quic/masque/masque_tcp_server_bin.cc b/quiche/quic/masque/masque_tcp_server_bin.cc index 396d404..8b1b4ed 100644 --- a/quiche/quic/masque/masque_tcp_server_bin.cc +++ b/quiche/quic/masque/masque_tcp_server_bin.cc
@@ -120,6 +120,8 @@ namespace { +constexpr absl::string_view kInfo = "TS"; + absl::string_view RemoveParameters(absl::string_view value) { std::vector<absl::string_view> split = absl::StrSplit(value, absl::MaxSplits(';', 1)); @@ -339,7 +341,7 @@ MasqueH2Connection::Visitor* visitor) : socket_(connected_socket), event_loop_(event_loop), - connection_(CreateSsl(ctx), is_server, visitor) { + connection_(CreateSsl(ctx), is_server, visitor, kInfo) { if (!event_loop_->RegisterSocket(socket_, kSocketEventReadable, this)) { QUICHE_LOG(FATAL) << "Failed to register connection socket with the event loop"; @@ -409,7 +411,8 @@ const MasqueConnectionPool::DnsConfig& dns_config) : event_loop_(GetDefaultEventLoop()->Create(QuicDefaultClock::Get())), connection_pool_(event_loop_.get(), client_ssl_ctx, - disable_certificate_verification, dns_config, this) {} + disable_certificate_verification, dns_config, this, + kInfo) {} MasqueTcpServer(const MasqueTcpServer&) = delete; MasqueTcpServer(MasqueTcpServer&&) = delete;