Add quic_logging

net/quic/core/quic_session.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 "net/quic/core/quic_session.h"
 
 #include "base/memory/ptr_util.h"
 #include "base/stl_util.h"
 #include "net/quic/core/crypto/proof_verifier.h"
 #include "net/quic/core/quic_connection.h"
 #include "net/quic/core/quic_flags.h"
 #include "net/quic/core/quic_flow_controller.h"
 #include "net/quic/platform/api/quic_bug_tracker.h"
+#include "net/quic/platform/api/quic_logging.h"
 #include "net/quic/platform/api/quic_str_cat.h"
 
 using base::StringPiece;
 using std::string;
 
 namespace net {
 
 #define ENDPOINT \
   (perspective() == Perspective::IS_SERVER ? "Server: " : " Client: ")
 
@@ skipping 22 matching lines @@
 
 void QuicSession::Initialize() {
   connection_->set_visitor(this);
   connection_->SetFromConfig(config_);
 
   DCHECK_EQ(kCryptoStreamId, GetCryptoStream()->id());
   static_stream_map_[kCryptoStreamId] = GetCryptoStream();
 }
 
 QuicSession::~QuicSession() {
-  DLOG_IF(WARNING, num_locally_closed_incoming_streams_highest_offset() >
-                       max_open_incoming_streams_)
+  QUIC_LOG_IF(WARNING, num_locally_closed_incoming_streams_highest_offset() >
+                           max_open_incoming_streams_)
       << "Surprisingly high number of locally closed peer initiated streams"
          "still waiting for final byte offset: "
       << num_locally_closed_incoming_streams_highest_offset();
-  DLOG_IF(WARNING, GetNumLocallyClosedOutgoingStreamsHighestOffset() >
-                       max_open_outgoing_streams_)
+  QUIC_LOG_IF(WARNING, GetNumLocallyClosedOutgoingStreamsHighestOffset() >
+                           max_open_outgoing_streams_)
       << "Surprisingly high number of locally closed self initiated streams"
          "still waiting for final byte offset: "
       << GetNumLocallyClosedOutgoingStreamsHighestOffset();
 }
 
 void QuicSession::OnStreamFrame(const QuicStreamFrame& frame) {
   // TODO(rch) deal with the error case of stream id 0.
   QuicStreamId stream_id = frame.stream_id;
   QuicStream* stream = GetOrCreateStream(stream_id);
   if (!stream) {
@@ skipping 66 matching lines @@
 
 void QuicSession::OnPathDegrading() {}
 
 void QuicSession::OnWindowUpdateFrame(const QuicWindowUpdateFrame& frame) {
   // Stream may be closed by the time we receive a WINDOW_UPDATE, so we can't
   // assume that it still exists.
   QuicStreamId stream_id = frame.stream_id;
   if (stream_id == kConnectionLevelId) {
     // This is a window update that applies to the connection, rather than an
     // individual stream.
-    DVLOG(1) << ENDPOINT << "Received connection level flow control window "
-                            "update with byte offset: "
-             << frame.byte_offset;
+    QUIC_DLOG(INFO) << ENDPOINT
+                    << "Received connection level flow control window "
+                       "update with byte offset: "
+                    << frame.byte_offset;
     flow_controller_.UpdateSendWindowOffset(frame.byte_offset);
     return;
   }
   QuicStream* stream = GetOrCreateStream(stream_id);
   if (stream != nullptr) {
     stream->OnWindowUpdateFrame(frame);
   }
 }
 
 void QuicSession::OnBlockedFrame(const QuicBlockedFrame& frame) {
   // TODO(rjshade): Compare our flow control receive windows for specified
   //                streams: if we have a large window then maybe something
   //                had gone wrong with the flow control accounting.
-  DVLOG(1) << ENDPOINT
-           << "Received BLOCKED frame with stream id: " << frame.stream_id;
+  QUIC_DLOG(INFO) << ENDPOINT << "Received BLOCKED frame with stream id: "
+                  << frame.stream_id;
 }
 
 bool QuicSession::CheckStreamNotBusyLooping(QuicStream* stream,
                                             uint64_t previous_bytes_written,
                                             bool previous_fin_sent) {
   if (  // Stream should not be closed.
       !stream->write_side_closed() &&
       // Not connection flow control blocked.
       !flow_controller_.IsBlocked() &&
       // Detect lack of forward progress.
       previous_bytes_written == stream->stream_bytes_written() &&
       previous_fin_sent == stream->fin_sent()) {
     stream->set_busy_counter(stream->busy_counter() + 1);
-    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) << "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) {
-      LOG(ERROR) << "Detected busy loop on stream id " << stream->id()
-                 << " stream_bytes_written " << stream->stream_bytes_written()
-                 << " fin " << stream->fin_sent();
+      QUIC_LOG(ERROR) << "Detected busy loop on stream id " << stream->id()
+                      << " stream_bytes_written "
+                      << stream->stream_bytes_written() << " fin "
+                      << stream->fin_sent();
       return false;
     }
   } else {
     stream->set_busy_counter(0);
   }
   return true;
 }
 
 void QuicSession::OnCanWrite() {
   // We limit the number of writes to the number of pending streams. If more
@@ skipping 32 matching lines @@
     if (!connection_->CanWriteStreamData()) {
       return;
     }
     currently_writing_stream_id_ = write_blocked_streams_.PopFront();
     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();
-      DVLOG(1) << "stream " << stream->id() << " bytes_written "
-               << previous_bytes_written << " fin " << previous_fin_sent;
+      QUIC_DVLOG(1) << "stream " << stream->id() << " bytes_written "
+                    << previous_bytes_written << " fin " << previous_fin_sent;
       stream->OnCanWrite();
       DCHECK(CheckStreamNotBusyLooping(stream, previous_bytes_written,
                                        previous_fin_sent));
     }
     currently_writing_stream_id_ = 0;
   }
 }
 
 bool QuicSession::WillingAndAbleToWrite() const {
   // If the crypto or headers streams are blocked, we want to schedule a write -
@@ skipping 81 matching lines @@
 void QuicSession::InsertLocallyClosedStreamsHighestOffset(
     const QuicStreamId id,
     QuicStreamOffset offset) {
   locally_closed_streams_highest_offset_[id] = offset;
   if (IsIncomingStream(id)) {
     ++num_locally_closed_incoming_streams_highest_offset_;
   }
 }
 
 void QuicSession::CloseStreamInner(QuicStreamId stream_id, bool locally_reset) {
-  DVLOG(1) << ENDPOINT << "Closing stream " << stream_id;
+  QUIC_DLOG(INFO) << ENDPOINT << "Closing stream " << stream_id;
 
   DynamicStreamMap::iterator it = dynamic_stream_map_.find(stream_id);
   if (it == dynamic_stream_map_.end()) {
     // When CloseStreamInner has been called recursively (via
     // QuicStream::OnClose), the stream will already have been deleted
     // from stream_map_, so return immediately.
-    DVLOG(1) << ENDPOINT << "Stream is already closed: " << stream_id;
+    QUIC_DLOG(INFO) << ENDPOINT << "Stream is already closed: " << stream_id;
     return;
   }
   QuicStream* stream = it->second.get();
 
   // Tell the stream that a RST has been sent.
   if (locally_reset) {
     stream->set_rst_sent(true);
   }
 
   closed_streams_.push_back(std::move(it->second));
@@ skipping 24 matching lines @@
 
 void QuicSession::UpdateFlowControlOnFinalReceivedByteOffset(
     QuicStreamId stream_id,
     QuicStreamOffset final_byte_offset) {
   std::map<QuicStreamId, QuicStreamOffset>::iterator it =
       locally_closed_streams_highest_offset_.find(stream_id);
   if (it == locally_closed_streams_highest_offset_.end()) {
     return;
   }
 
-  DVLOG(1) << ENDPOINT << "Received final byte offset " << final_byte_offset
-           << " for stream " << stream_id;
+  QUIC_DVLOG(1) << ENDPOINT << "Received final byte offset "
+                << final_byte_offset << " for stream " << stream_id;
   QuicByteCount offset_diff = final_byte_offset - it->second;
   if (flow_controller_.UpdateHighestReceivedOffset(
           flow_controller_.highest_received_byte_offset() + offset_diff)) {
     // If the final offset violates flow control, close the connection now.
     if (flow_controller_.FlowControlViolation()) {
       connection_->CloseConnection(
           QUIC_FLOW_CONTROL_RECEIVED_TOO_MUCH_DATA,
           "Connection level flow control violation",
           ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
       return;
@@ skipping 83 matching lines @@
 }
 
 void QuicSession::AdjustInitialFlowControlWindows(size_t stream_window) {
   const float session_window_multiplier =
       config_.GetInitialStreamFlowControlWindowToSend()
           ? static_cast<float>(
                 config_.GetInitialSessionFlowControlWindowToSend()) /
                 config_.GetInitialStreamFlowControlWindowToSend()
           : 1.5;
 
-  DVLOG(1) << ENDPOINT << "Set stream receive window to " << stream_window;
+  QUIC_DVLOG(1) << ENDPOINT << "Set stream receive window to " << stream_window;
   config_.SetInitialStreamFlowControlWindowToSend(stream_window);
 
   size_t session_window = session_window_multiplier * stream_window;
-  DVLOG(1) << ENDPOINT << "Set session receive window to " << session_window;
+  QUIC_DVLOG(1) << ENDPOINT << "Set session receive window to "
+                << session_window;
   config_.SetInitialSessionFlowControlWindowToSend(session_window);
   flow_controller_.UpdateReceiveWindowSize(session_window);
   // Inform all existing streams about the new window.
   for (auto const& kv : static_stream_map_) {
     kv.second->flow_controller()->UpdateReceiveWindowSize(stream_window);
   }
   for (auto const& kv : dynamic_stream_map_) {
     kv.second->flow_controller()->UpdateReceiveWindowSize(stream_window);
   }
 }
@@ skipping 16 matching lines @@
   if (IsClosedStream(frame.stream_id)) {
     // The RST frame contains the final byte offset for the stream: we can now
     // update the connection level flow controller if needed.
     UpdateFlowControlOnFinalReceivedByteOffset(frame.stream_id,
                                                frame.byte_offset);
   }
 }
 
 void QuicSession::OnNewStreamFlowControlWindow(QuicStreamOffset new_window) {
   if (new_window < kMinimumFlowControlSendWindow) {
-    LOG(ERROR) << "Peer sent us an invalid stream flow control send window: "
-               << new_window
-               << ", below default: " << kMinimumFlowControlSendWindow;
+    QUIC_LOG_FIRST_N(ERROR, 1)
+        << "Peer sent us an invalid stream flow control send window: "
+        << new_window << ", below default: " << kMinimumFlowControlSendWindow;
     if (connection_->connected()) {
       connection_->CloseConnection(
           QUIC_FLOW_CONTROL_INVALID_WINDOW, "New stream window too low",
           ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
     }
     return;
   }
 
   // Inform all existing streams about the new window.
   for (auto const& kv : static_stream_map_) {
     kv.second->UpdateSendWindowOffset(new_window);
   }
   for (auto const& kv : dynamic_stream_map_) {
     kv.second->UpdateSendWindowOffset(new_window);
   }
 }
 
 void QuicSession::OnNewSessionFlowControlWindow(QuicStreamOffset new_window) {
   if (new_window < kMinimumFlowControlSendWindow) {
-    LOG(ERROR) << "Peer sent us an invalid session flow control send window: "
-               << new_window
-               << ", below default: " << kMinimumFlowControlSendWindow;
+    QUIC_LOG_FIRST_N(ERROR, 1)
+        << "Peer sent us an invalid session flow control send window: "
+        << new_window << ", below default: " << kMinimumFlowControlSendWindow;
     if (connection_->connected()) {
       connection_->CloseConnection(
           QUIC_FLOW_CONTROL_INVALID_WINDOW, "New connection window too low",
           ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
     }
     return;
   }
 
   flow_controller_.UpdateSendWindowOffset(new_window);
 }
@@ skipping 17 matching lines @@
 
     case HANDSHAKE_CONFIRMED:
       QUIC_BUG_IF(!config_.negotiated())
           << ENDPOINT << "Handshake confirmed without parameter negotiation.";
       // Discard originally encrypted packets, since they can't be decrypted by
       // the peer.
       connection_->NeuterUnencryptedPackets();
       break;
 
     default:
-      LOG(ERROR) << ENDPOINT << "Got unknown handshake event: " << event;
+      QUIC_LOG(ERROR) << ENDPOINT << "Got unknown handshake event: " << event;
   }
 }
 
 void QuicSession::OnCryptoHandshakeMessageSent(
     const CryptoHandshakeMessage& /*message*/) {}
 
 void QuicSession::OnCryptoHandshakeMessageReceived(
     const CryptoHandshakeMessage& /*message*/) {}
 
 QuicConfig* QuicSession::config() {
   return &config_;
 }
 
 void QuicSession::ActivateStream(std::unique_ptr<QuicStream> stream) {
   QuicStreamId stream_id = stream->id();
-  DVLOG(1) << ENDPOINT << "num_streams: " << dynamic_stream_map_.size()
-           << ". activating " << stream_id;
+  QUIC_DLOG(INFO) << ENDPOINT << "num_streams: " << dynamic_stream_map_.size()
+                  << ". activating " << stream_id;
   DCHECK(!base::ContainsKey(dynamic_stream_map_, stream_id));
   DCHECK(!base::ContainsKey(static_stream_map_, stream_id));
   dynamic_stream_map_[stream_id] = std::move(stream);
   if (IsIncomingStream(stream_id)) {
     ++num_dynamic_incoming_streams_;
   }
   // Increase the number of streams being emulated when a new one is opened.
   connection_->SetNumOpenStreams(dynamic_stream_map_.size());
 }
 
@@ skipping 28 matching lines @@
   }
 
   // Check if the new number of available streams would cause the number of
   // available streams to exceed the limit.  Note that the peer can create
   // only alternately-numbered streams.
   size_t additional_available_streams =
       (stream_id - largest_peer_created_stream_id_) / 2 - 1;
   size_t new_num_available_streams =
       GetNumAvailableStreams() + additional_available_streams;
   if (new_num_available_streams > MaxAvailableStreams()) {
-    DVLOG(1) << ENDPOINT
-             << "Failed to create a new incoming stream with id:" << stream_id
-             << ".  There are already " << GetNumAvailableStreams()
-             << " streams available, which would become "
-             << new_num_available_streams << ", which exceeds the limit "
-             << MaxAvailableStreams() << ".";
+    QUIC_DLOG(INFO) << ENDPOINT
+                    << "Failed to create a new incoming stream with id:"
+                    << stream_id << ".  There are already "
+                    << GetNumAvailableStreams()
+                    << " streams available, which would become "
+                    << new_num_available_streams << ", which exceeds the limit "
+                    << MaxAvailableStreams() << ".";
     connection()->CloseConnection(
         QUIC_TOO_MANY_AVAILABLE_STREAMS,
         QuicStrCat(new_num_available_streams, " above ", MaxAvailableStreams()),
         ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
     return false;
   }
   for (QuicStreamId id = largest_peer_created_stream_id_ + 2; id < stream_id;
        id += 2) {
     available_streams_.insert(id);
   }
@@ skipping 39 matching lines @@
     // Refuse to open the stream.
     SendRstStream(stream_id, QUIC_REFUSED_STREAM, 0);
     return nullptr;
   }
 
   return CreateIncomingDynamicStream(stream_id);
 }
 
 void QuicSession::set_max_open_incoming_streams(
     size_t max_open_incoming_streams) {
-  DVLOG(1) << "Setting max_open_incoming_streams_ to "
-           << max_open_incoming_streams;
+  QUIC_DVLOG(1) << "Setting max_open_incoming_streams_ to "
+                << max_open_incoming_streams;
   max_open_incoming_streams_ = max_open_incoming_streams;
-  DVLOG(1) << "MaxAvailableStreams() became " << MaxAvailableStreams();
+  QUIC_DVLOG(1) << "MaxAvailableStreams() became " << MaxAvailableStreams();
 }
 
 void QuicSession::set_max_open_outgoing_streams(
     size_t max_open_outgoing_streams) {
-  DVLOG(1) << "Setting max_open_outgoing_streams_ to "
-           << max_open_outgoing_streams;
+  QUIC_DVLOG(1) << "Setting max_open_outgoing_streams_ to "
+                << max_open_outgoing_streams;
   max_open_outgoing_streams_ = max_open_outgoing_streams;
 }
 
 bool QuicSession::goaway_sent() const {
   return connection_->goaway_sent();
 }
 
 bool QuicSession::goaway_received() const {
   return connection_->goaway_received();
 }
@@ skipping 100 matching lines @@
 
 size_t QuicSession::MaxAvailableStreams() const {
   return max_open_incoming_streams_ * kMaxAvailableStreamsMultiplier;
 }
 
 bool QuicSession::IsIncomingStream(QuicStreamId id) const {
   return id % 2 != next_outgoing_stream_id_ % 2;
 }
 
 }  // namespace net