Add quic_logging

net/tools/quic/end_to_end_test.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include <stddef.h>
 #include <sys/epoll.h>
 
 #include <cstdint>
 #include <list>
 #include <memory>
@@ skipping 12 matching lines @@
 #include "net/quic/core/crypto/aes_128_gcm_12_encrypter.h"
 #include "net/quic/core/crypto/null_encrypter.h"
 #include "net/quic/core/quic_client_session_base.h"
 #include "net/quic/core/quic_flags.h"
 #include "net/quic/core/quic_framer.h"
 #include "net/quic/core/quic_packet_creator.h"
 #include "net/quic/core/quic_packets.h"
 #include "net/quic/core/quic_server_id.h"
 #include "net/quic/core/quic_session.h"
 #include "net/quic/core/quic_utils.h"
+#include "net/quic/platform/api/quic_logging.h"
 #include "net/quic/platform/api/quic_socket_address.h"
 #include "net/quic/platform/api/quic_str_cat.h"
 #include "net/quic/platform/api/quic_text_utils.h"
 #include "net/quic/test_tools/crypto_test_utils.h"
 #include "net/quic/test_tools/quic_config_peer.h"
 #include "net/quic/test_tools/quic_connection_peer.h"
 #include "net/quic/test_tools/quic_flow_controller_peer.h"
 #include "net/quic/test_tools/quic_sent_packet_manager_peer.h"
 #include "net/quic/test_tools/quic_session_peer.h"
 #include "net/quic/test_tools/quic_spdy_session_peer.h"
@@ skipping 233 matching lines @@
         client_writer_(nullptr),
         server_writer_(nullptr),
         server_started_(false),
         chlo_multiplier_(0),
         stream_factory_(nullptr),
         support_server_push_(false) {
     client_supported_versions_ = GetParam().client_supported_versions;
     server_supported_versions_ = GetParam().server_supported_versions;
     negotiated_version_ = GetParam().negotiated_version;
 
-    VLOG(1) << "Using Configuration: " << GetParam();
+    QUIC_LOG(INFO) << "Using Configuration: " << GetParam();
 
     // Use different flow control windows for client/server.
     client_config_.SetInitialStreamFlowControlWindowToSend(
         2 * kInitialStreamFlowControlWindowForTest);
     client_config_.SetInitialSessionFlowControlWindowToSend(
         2 * kInitialSessionFlowControlWindowForTest);
     server_config_.SetInitialStreamFlowControlWindowToSend(
         3 * kInitialStreamFlowControlWindowForTest);
     server_config_.SetInitialSessionFlowControlWindowToSend(
         3 * kInitialSessionFlowControlWindowForTest);
@@ skipping 34 matching lines @@
     set_client_initial_stream_flow_control_receive_window(kClientIFCW);
     set_client_initial_session_flow_control_receive_window(
         kSessionToStreamRatio * kClientIFCW);
     set_server_initial_stream_flow_control_receive_window(kServerIFCW);
     set_server_initial_session_flow_control_receive_window(
         kSessionToStreamRatio * kServerIFCW);
   }
 
   void set_client_initial_stream_flow_control_receive_window(uint32_t window) {
     CHECK(client_.get() == nullptr);
-    DVLOG(1) << "Setting client initial stream flow control window: " << window;
+    QUIC_DLOG(INFO) << "Setting client initial stream flow control window: "
+                    << window;
     client_config_.SetInitialStreamFlowControlWindowToSend(window);
   }
 
   void set_client_initial_session_flow_control_receive_window(uint32_t window) {
     CHECK(client_.get() == nullptr);
-    DVLOG(1) << "Setting client initial session flow control window: "
-             << window;
+    QUIC_DLOG(INFO) << "Setting client initial session flow control window: "
+                    << window;
     client_config_.SetInitialSessionFlowControlWindowToSend(window);
   }
 
   void set_server_initial_stream_flow_control_receive_window(uint32_t window) {
     CHECK(server_thread_.get() == nullptr);
-    DVLOG(1) << "Setting server initial stream flow control window: " << window;
+    QUIC_DLOG(INFO) << "Setting server initial stream flow control window: "
+                    << window;
     server_config_.SetInitialStreamFlowControlWindowToSend(window);
   }
 
   void set_server_initial_session_flow_control_receive_window(uint32_t window) {
     CHECK(server_thread_.get() == nullptr);
-    DVLOG(1) << "Setting server initial session flow control window: "
-             << window;
+    QUIC_DLOG(INFO) << "Setting server initial session flow control window: "
+                    << window;
     server_config_.SetInitialSessionFlowControlWindowToSend(window);
   }
 
   const QuicSentPacketManagerInterface*
   GetSentPacketManagerFromFirstServerSession() const {
     QuicDispatcher* dispatcher =
         QuicServerPeer::GetDispatcher(server_thread_->server());
     QuicSession* session = dispatcher->session_map().begin()->second.get();
     return &session->connection()->sent_packet_manager();
   }
@@ skipping 965 matching lines @@
     case kRENO:
       expected_congestion_control_type = kReno;
       break;
     case kTBBR:
       expected_congestion_control_type = kBBR;
       break;
     case kQBIC:
       expected_congestion_control_type = kCubicBytes;
       break;
     default:
-      DLOG(FATAL) << "Unexpected congestion control tag";
+      QUIC_DLOG(FATAL) << "Unexpected congestion control tag";
   }
 
   server_thread_->Pause();
   EXPECT_EQ(expected_congestion_control_type,
             QuicSentPacketManagerPeer::GetSendAlgorithm(
                 *static_cast<const QuicSentPacketManager*>(
                     GetSentPacketManagerFromFirstServerSession()))
                 ->GetCongestionControlType());
   server_thread_->Resume();
 }
@@ skipping 578 matching lines @@
 
  private:
   int num_notifications_;
 };
 
 class TestResponseListener : public QuicClient::ResponseListener {
  public:
   void OnCompleteResponse(QuicStreamId id,
                           const SpdyHeaderBlock& response_headers,
                           const string& response_body) override {
-    string debug_string = response_headers.DebugString();
-    DVLOG(1) << "response for stream " << id << " " << debug_string << "\n"
-             << response_body;
+    QUIC_DVLOG(1) << "response for stream " << id << " "
+                  << response_headers.DebugString() << "\n"
+                  << response_body;
   }
 };
 
 TEST_P(EndToEndTest, AckNotifierWithPacketLossAndBlockedSocket) {
   // Verify that even in the presence of packet loss and occasionally blocked
   // socket,  an AckNotifierDelegate will get informed that the data it is
   // interested in has been ACKed. This tests end-to-end ACK notification, and
   // demonstrates that retransmissions do not break this functionality.
   if (!BothSidesSupportStatelessRejects()) {
     // TODO(jokulik): Until we support redundant SREJ packets, don't
@@ skipping 249 matching lines @@
   EXPECT_EQ(kFooResponseBody, client_->SendSynchronousRequest("/foo"));
   EXPECT_EQ("200", client_->response_headers()->find(":status")->second);
 
   std::unique_ptr<QuicEncryptedPacket> packet(ConstructEncryptedPacket(
       client_->client()->session()->connection()->connection_id(), false, false,
       false, kDefaultPathId, 1, "At least 20 characters.",
       PACKET_8BYTE_CONNECTION_ID, PACKET_6BYTE_PACKET_NUMBER));
   // Damage the encrypted data.
   string damaged_packet(packet->data(), packet->length());
   damaged_packet[30] ^= 0x01;
-  DVLOG(1) << "Sending bad packet.";
+  QUIC_DLOG(INFO) << "Sending bad packet.";
   client_writer_->WritePacket(
       damaged_packet.data(), damaged_packet.length(),
       client_->client()->GetLatestClientAddress().host(), server_address_,
       nullptr);
   // Give the server time to process the packet.
   base::PlatformThread::Sleep(base::TimeDelta::FromMilliseconds(100));
   // This error is sent to the connection's OnError (which ignores it), so the
   // dispatcher doesn't see it.
   // Pause the server so we can access the server's internals without races.
   server_thread_->Pause();
@@ skipping 15 matching lines @@
                                     QuicSpdySession* session,
                                     QuicHttpResponseCache* response_cache,
                                     string response_body)
       : QuicSimpleServerStream(id, session, response_cache),
         response_body_(std::move(response_body)) {}
 
   ~ServerStreamWithErrorResponseBody() override {}
 
  protected:
   void SendErrorResponse() override {
-    DVLOG(1) << "Sending error response for stream " << id();
+    QUIC_DLOG(INFO) << "Sending error response for stream " << id();
     SpdyHeaderBlock headers;
     headers[":status"] = "500";
     headers["content-length"] =
         QuicTextUtils::Uint64ToString(response_body_.size());
     // This method must call CloseReadSide to cause the test case, StopReading
     // is not sufficient.
     QuicStreamPeer::CloseReadSide(this);
     SendHeadersAndBody(std::move(headers), response_body_);
   }
 
@@ skipping 30 matching lines @@
   ~ServerStreamThatDropsBody() override {}
 
  protected:
   void OnDataAvailable() override {
     while (HasBytesToRead()) {
       struct iovec iov;
       if (GetReadableRegions(&iov, 1) == 0) {
         // No more data to read.
         break;
       }
-      DVLOG(1) << "Processed " << iov.iov_len << " bytes for stream " << id();
+      QUIC_DVLOG(1) << "Processed " << iov.iov_len << " bytes for stream "
+                    << id();
       MarkConsumed(iov.iov_len);
     }
 
     if (!sequencer()->IsClosed()) {
       sequencer()->SetUnblocked();
       return;
     }
 
     // If the sequencer is closed, then all the body, including the fin, has
     // been consumed.
@@ skipping 357 matching lines @@
                         "https://example.com/script.js",
                         "https://fonts.example.com/font.woff",
                         "https://example.com/logo-hires.jpg"};
   AddRequestAndResponseWithServerPush("example.com", "/push_example", kBody,
                                       push_urls, kNumResources, 0);
 
   client_->client()->set_response_listener(
       std::unique_ptr<QuicClientBase::ResponseListener>(
           new TestResponseListener));
 
-  DVLOG(1) << "send request for /push_example";
+  QUIC_DVLOG(1) << "send request for /push_example";
   EXPECT_EQ(kBody, client_->SendSynchronousRequest(
                        "https://example.com/push_example"));
   QuicHeadersStream* headers_stream =
       QuicSpdySessionPeer::GetHeadersStream(client_->client()->session());
   QuicStreamSequencer* sequencer = QuicStreamPeer::sequencer(headers_stream);
   // Headers stream's sequencer buffer shouldn't be released because server push
   // hasn't finished yet.
   EXPECT_TRUE(QuicStreamSequencerPeer::IsUnderlyingBufferAllocated(sequencer));
 
   for (const string& url : push_urls) {
-    DVLOG(1) << "send request for pushed stream on url " << url;
+    QUIC_DVLOG(1) << "send request for pushed stream on url " << url;
     string expected_body =
         QuicStrCat("This is server push response body for ", url);
     string response_body = client_->SendSynchronousRequest(url);
-    DVLOG(1) << "response body " << response_body;
+    QUIC_DVLOG(1) << "response body " << response_body;
     EXPECT_EQ(expected_body, response_body);
   }
   EXPECT_NE(
       FLAGS_quic_reloadable_flag_quic_headers_stream_release_sequencer_buffer &&
           FLAGS_quic_reloadable_flag_quic_reduce_sequencer_buffer_memory_life_time,  // NOLINT
       QuicStreamSequencerPeer::IsUnderlyingBufferAllocated(sequencer));
 }
 
 TEST_P(EndToEndTestServerPush, ServerPushUnderLimit) {
   // Tests that sending a request which has 4 push resources will trigger server
@@ skipping 23 matching lines @@
 
   // Send the first request: this will trigger the server to send all the push
   // resources associated with this request, and these will be cached by the
   // client.
   EXPECT_EQ(kBody, client_->SendSynchronousRequest(
                        "https://example.com/push_example"));
 
   for (const string& url : push_urls) {
     // Sending subsequent requesets will not actually send anything on the wire,
     // as the responses are already in the client's cache.
-    DVLOG(1) << "send request for pushed stream on url " << url;
+    QUIC_DVLOG(1) << "send request for pushed stream on url " << url;
     string expected_body =
         QuicStrCat("This is server push response body for ", url);
     string response_body = client_->SendSynchronousRequest(url);
-    DVLOG(1) << "response body " << response_body;
+    QUIC_DVLOG(1) << "response body " << response_body;
     EXPECT_EQ(expected_body, response_body);
   }
   // Expect only original request has been sent and push responses have been
   // received as normal response.
   EXPECT_EQ(1u, client_->num_requests());
   EXPECT_EQ(1u + kNumResources, client_->num_responses());
 }
 
 TEST_P(EndToEndTestServerPush, ServerPushOverLimitNonBlocking) {
   // Tests that when streams are not blocked by flow control or congestion
@@ skipping 251 matching lines @@
   QuicStreamSequencer* sequencer = QuicStreamPeer::sequencer(headers_stream);
   EXPECT_NE(
       FLAGS_quic_reloadable_flag_quic_headers_stream_release_sequencer_buffer &&
           FLAGS_quic_reloadable_flag_quic_reduce_sequencer_buffer_memory_life_time,  // NOLINT
       QuicStreamSequencerPeer::IsUnderlyingBufferAllocated(sequencer));
 }
 
 class EndToEndBufferedPacketsTest : public EndToEndTest {
  public:
   void CreateClientWithWriter() override {
-    LOG(ERROR) << "create client with reorder_writer_ ";
+    QUIC_LOG(ERROR) << "create client with reorder_writer_ ";
     reorder_writer_ = new PacketReorderingWriter();
     client_.reset(EndToEndTest::CreateQuicClient(reorder_writer_));
   }
 
   void SetUp() override {
     // Don't initialize client writer in base class.
     server_writer_ = new PacketDroppingTestWriter();
   }
 
  protected:
@@ skipping 30 matching lines @@
   client_->WaitForResponse();
   EXPECT_EQ(kBarResponseBody, client_->response_body());
   QuicConnectionStats client_stats =
       client_->client()->session()->connection()->GetStats();
   EXPECT_EQ(0u, client_stats.packets_lost);
   EXPECT_EQ(1, client_->client()->GetNumSentClientHellos());
 }
 }  // namespace
 }  // namespace test
 }  // namespace net