| Index: net/quic/core/quic_connection.cc
|
| diff --git a/net/quic/core/quic_connection.cc b/net/quic/core/quic_connection.cc
|
| index a67efdaf9dfa34104f717fe39576e68565dcb01c..6262fd3a744e9d3045b63f1244db0eb4d8c817bd 100644
|
| --- a/net/quic/core/quic_connection.cc
|
| +++ b/net/quic/core/quic_connection.cc
|
| @@ -15,7 +15,6 @@
|
| #include <utility>
|
|
|
| #include "base/format_macros.h"
|
| -#include "base/logging.h"
|
| #include "base/macros.h"
|
| #include "base/metrics/histogram_macros.h"
|
| #include "base/stl_util.h"
|
| @@ -34,6 +33,7 @@
|
| #include "net/quic/core/quic_sent_packet_manager.h"
|
| #include "net/quic/core/quic_utils.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"
|
| #include "net/quic/platform/api/quic_text_utils.h"
|
|
|
| @@ -271,8 +271,8 @@ QuicConnection::QuicConnection(QuicConnectionId connection_id,
|
| goaway_received_(false),
|
| multipath_enabled_(false),
|
| write_error_occured_(false) {
|
| - DVLOG(1) << ENDPOINT
|
| - << "Created connection with connection_id: " << connection_id;
|
| + QUIC_DLOG(INFO) << ENDPOINT
|
| + << "Created connection with connection_id: " << connection_id;
|
| framer_.set_visitor(this);
|
| if (!FLAGS_quic_reloadable_flag_quic_receive_packet_once_decrypted) {
|
| last_stop_waiting_frame_.least_unacked = 0;
|
| @@ -436,14 +436,14 @@ void QuicConnection::OnPublicResetPacket(const QuicPublicResetPacket& packet) {
|
| debug_visitor_->OnPublicResetPacket(packet);
|
| }
|
| const string error_details = "Received public reset.";
|
| - DVLOG(1) << ENDPOINT << error_details;
|
| + QUIC_DLOG(INFO) << ENDPOINT << error_details;
|
| TearDownLocalConnectionState(QUIC_PUBLIC_RESET, error_details,
|
| ConnectionCloseSource::FROM_PEER);
|
| }
|
|
|
| bool QuicConnection::OnProtocolVersionMismatch(QuicVersion received_version) {
|
| - DVLOG(1) << ENDPOINT << "Received packet with mismatched version "
|
| - << received_version;
|
| + QUIC_DLOG(INFO) << ENDPOINT << "Received packet with mismatched version "
|
| + << received_version;
|
| // TODO(satyamshekhar): Implement no server state in this mode.
|
| if (perspective_ == Perspective::IS_CLIENT) {
|
| const string error_details = "Protocol version mismatch.";
|
| @@ -488,7 +488,7 @@ bool QuicConnection::OnProtocolVersionMismatch(QuicVersion received_version) {
|
| if (debug_visitor_ != nullptr) {
|
| debug_visitor_->OnSuccessfulVersionNegotiation(received_version);
|
| }
|
| - DVLOG(1) << ENDPOINT << "version negotiated " << received_version;
|
| + QUIC_DLOG(INFO) << ENDPOINT << "version negotiated " << received_version;
|
|
|
| // Store the new version.
|
| framer_.set_version(received_version);
|
| @@ -526,7 +526,7 @@ void QuicConnection::OnVersionNegotiationPacket(
|
| const string error_details =
|
| "Server already supports client's version and should have accepted the "
|
| "connection.";
|
| - DLOG(WARNING) << error_details;
|
| + QUIC_DLOG(WARNING) << error_details;
|
| TearDownLocalConnectionState(QUIC_INVALID_VERSION_NEGOTIATION_PACKET,
|
| error_details,
|
| ConnectionCloseSource::FROM_SELF);
|
| @@ -544,8 +544,8 @@ void QuicConnection::OnVersionNegotiationPacket(
|
| return;
|
| }
|
|
|
| - DVLOG(1) << ENDPOINT
|
| - << "Negotiated version: " << QuicVersionToString(version());
|
| + QUIC_DLOG(INFO) << ENDPOINT
|
| + << "Negotiated version: " << QuicVersionToString(version());
|
| server_supported_versions_ = packet.versions;
|
| version_negotiation_state_ = NEGOTIATION_IN_PROGRESS;
|
| RetransmitUnackedPackets(ALL_UNACKED_RETRANSMISSION);
|
| @@ -558,8 +558,9 @@ bool QuicConnection::OnUnauthenticatedPublicHeader(
|
| }
|
|
|
| ++stats_.packets_dropped;
|
| - DVLOG(1) << ENDPOINT << "Ignoring packet from unexpected ConnectionId: "
|
| - << header.connection_id << " instead of " << connection_id_;
|
| + QUIC_DLOG(INFO) << ENDPOINT
|
| + << "Ignoring packet from unexpected ConnectionId: "
|
| + << header.connection_id << " instead of " << connection_id_;
|
| if (debug_visitor_ != nullptr) {
|
| debug_visitor_->OnIncorrectConnectionId(header.connection_id);
|
| }
|
| @@ -594,8 +595,8 @@ bool QuicConnection::OnUnauthenticatedHeader(const QuicPacketHeader& header) {
|
| // If this packet has already been seen, or the sender has told us that it
|
| // will not be retransmitted, then stop processing the packet.
|
| if (!received_packet_manager_.IsAwaitingPacket(header.packet_number)) {
|
| - DVLOG(1) << ENDPOINT << "Packet " << header.packet_number
|
| - << " no longer being waited for. Discarding.";
|
| + QUIC_DLOG(INFO) << ENDPOINT << "Packet " << header.packet_number
|
| + << " no longer being waited for. Discarding.";
|
| if (debug_visitor_ != nullptr) {
|
| debug_visitor_->OnDuplicatePacket(header.packet_number);
|
| }
|
| @@ -643,7 +644,7 @@ bool QuicConnection::OnPacketHeader(const QuicPacketHeader& header) {
|
| }
|
|
|
| --stats_.packets_dropped;
|
| - DVLOG(1) << ENDPOINT << "Received packet header: " << header;
|
| + QUIC_DVLOG(1) << ENDPOINT << "Received packet header: " << header;
|
| last_header_ = header;
|
| if (FLAGS_quic_reloadable_flag_quic_receive_packet_once_decrypted) {
|
| // An ack will be sent if a missing retransmittable packet was received;
|
| @@ -696,10 +697,10 @@ bool QuicConnection::OnAckFrame(const QuicAckFrame& incoming_ack) {
|
| if (debug_visitor_ != nullptr) {
|
| debug_visitor_->OnAckFrame(incoming_ack);
|
| }
|
| - DVLOG(1) << ENDPOINT << "OnAckFrame: " << incoming_ack;
|
| + QUIC_DVLOG(1) << ENDPOINT << "OnAckFrame: " << incoming_ack;
|
|
|
| if (last_header_.packet_number <= largest_seen_packet_with_ack_) {
|
| - DVLOG(1) << ENDPOINT << "Received an old ack frame: ignoring";
|
| + QUIC_DLOG(INFO) << ENDPOINT << "Received an old ack frame: ignoring";
|
| return true;
|
| }
|
|
|
| @@ -749,7 +750,8 @@ bool QuicConnection::OnStopWaitingFrame(const QuicStopWaitingFrame& frame) {
|
| DCHECK(connected_);
|
|
|
| if (last_header_.packet_number <= largest_seen_packet_with_stop_waiting_) {
|
| - DVLOG(1) << ENDPOINT << "Received an old stop waiting frame: ignoring";
|
| + QUIC_DLOG(INFO) << ENDPOINT
|
| + << "Received an old stop waiting frame: ignoring";
|
| return true;
|
| }
|
|
|
| @@ -791,21 +793,22 @@ bool QuicConnection::OnPingFrame(const QuicPingFrame& frame) {
|
|
|
| const char* QuicConnection::ValidateAckFrame(const QuicAckFrame& incoming_ack) {
|
| if (incoming_ack.largest_observed > packet_generator_.packet_number()) {
|
| - DLOG(WARNING) << ENDPOINT << "Peer's observed unsent packet:"
|
| - << incoming_ack.largest_observed << " vs "
|
| - << packet_generator_.packet_number();
|
| + QUIC_DLOG(WARNING) << ENDPOINT << "Peer's observed unsent packet:"
|
| + << incoming_ack.largest_observed << " vs "
|
| + << packet_generator_.packet_number();
|
| // We got an error for data we have not sent. Error out.
|
| return "Largest observed too high.";
|
| }
|
|
|
| if (incoming_ack.largest_observed <
|
| sent_packet_manager_->GetLargestObserved(incoming_ack.path_id)) {
|
| - VLOG(1) << ENDPOINT << "Peer's largest_observed packet decreased:"
|
| - << incoming_ack.largest_observed << " vs "
|
| - << sent_packet_manager_->GetLargestObserved(incoming_ack.path_id)
|
| - << " packet_number:" << last_header_.packet_number
|
| - << " largest seen with ack:" << largest_seen_packet_with_ack_
|
| - << " connection_id: " << connection_id_;
|
| + QUIC_LOG(INFO) << ENDPOINT << "Peer's largest_observed packet decreased:"
|
| + << incoming_ack.largest_observed << " vs "
|
| + << sent_packet_manager_->GetLargestObserved(
|
| + incoming_ack.path_id)
|
| + << " packet_number:" << last_header_.packet_number
|
| + << " largest seen with ack:" << largest_seen_packet_with_ack_
|
| + << " connection_id: " << connection_id_;
|
| // A new ack has a diminished largest_observed value. Error out.
|
| // If this was an old packet, we wouldn't even have checked.
|
| return "Largest observed too low.";
|
| @@ -827,18 +830,19 @@ const char* QuicConnection::ValidateStopWaitingFrame(
|
| const QuicStopWaitingFrame& stop_waiting) {
|
| if (stop_waiting.least_unacked <
|
| received_packet_manager_.peer_least_packet_awaiting_ack()) {
|
| - DLOG(ERROR) << ENDPOINT << "Peer's sent low least_unacked: "
|
| - << stop_waiting.least_unacked << " vs "
|
| - << received_packet_manager_.peer_least_packet_awaiting_ack();
|
| + QUIC_DLOG(ERROR)
|
| + << ENDPOINT
|
| + << "Peer's sent low least_unacked: " << stop_waiting.least_unacked
|
| + << " vs " << received_packet_manager_.peer_least_packet_awaiting_ack();
|
| // We never process old ack frames, so this number should only increase.
|
| return "Least unacked too small.";
|
| }
|
|
|
| if (stop_waiting.least_unacked > last_header_.packet_number) {
|
| - DLOG(ERROR) << ENDPOINT
|
| - << "Peer sent least_unacked:" << stop_waiting.least_unacked
|
| - << " greater than the enclosing packet number:"
|
| - << last_header_.packet_number;
|
| + QUIC_DLOG(ERROR) << ENDPOINT
|
| + << "Peer sent least_unacked:" << stop_waiting.least_unacked
|
| + << " greater than the enclosing packet number:"
|
| + << last_header_.packet_number;
|
| return "Least unacked too large.";
|
| }
|
|
|
| @@ -850,10 +854,10 @@ bool QuicConnection::OnRstStreamFrame(const QuicRstStreamFrame& frame) {
|
| if (debug_visitor_ != nullptr) {
|
| debug_visitor_->OnRstStreamFrame(frame);
|
| }
|
| - DVLOG(1) << ENDPOINT
|
| - << "RST_STREAM_FRAME received for stream: " << frame.stream_id
|
| - << " with error: "
|
| - << QuicRstStreamErrorCodeToString(frame.error_code);
|
| + QUIC_DLOG(INFO) << ENDPOINT
|
| + << "RST_STREAM_FRAME received for stream: " << frame.stream_id
|
| + << " with error: "
|
| + << QuicRstStreamErrorCodeToString(frame.error_code);
|
| visitor_->OnRstStream(frame);
|
| visitor_->PostProcessAfterData();
|
| should_last_packet_instigate_acks_ = true;
|
| @@ -866,14 +870,14 @@ bool QuicConnection::OnConnectionCloseFrame(
|
| if (debug_visitor_ != nullptr) {
|
| debug_visitor_->OnConnectionCloseFrame(frame);
|
| }
|
| - DVLOG(1) << ENDPOINT
|
| - << "Received ConnectionClose for connection: " << connection_id()
|
| - << ", with error: " << QuicErrorCodeToString(frame.error_code)
|
| - << " (" << frame.error_details << ")";
|
| + QUIC_DLOG(INFO) << ENDPOINT << "Received ConnectionClose for connection: "
|
| + << connection_id()
|
| + << ", with error: " << QuicErrorCodeToString(frame.error_code)
|
| + << " (" << frame.error_details << ")";
|
| if (frame.error_code == QUIC_BAD_MULTIPATH_FLAG) {
|
| - LOG(ERROR) << "Unexpected QUIC_BAD_MULTIPATH_FLAG error."
|
| - << " last_received_header: " << last_header_
|
| - << " encryption_level: " << encryption_level_;
|
| + QUIC_LOG_FIRST_N(ERROR, 10) << "Unexpected QUIC_BAD_MULTIPATH_FLAG error."
|
| + << " last_received_header: " << last_header_
|
| + << " encryption_level: " << encryption_level_;
|
| }
|
| TearDownLocalConnectionState(frame.error_code, frame.error_details,
|
| ConnectionCloseSource::FROM_PEER);
|
| @@ -885,10 +889,10 @@ bool QuicConnection::OnGoAwayFrame(const QuicGoAwayFrame& frame) {
|
| if (debug_visitor_ != nullptr) {
|
| debug_visitor_->OnGoAwayFrame(frame);
|
| }
|
| - DVLOG(1) << ENDPOINT << "GOAWAY_FRAME received with last good stream: "
|
| - << frame.last_good_stream_id
|
| - << " and error: " << QuicErrorCodeToString(frame.error_code)
|
| - << " and reason: " << frame.reason_phrase;
|
| + QUIC_DLOG(INFO) << ENDPOINT << "GOAWAY_FRAME received with last good stream: "
|
| + << frame.last_good_stream_id
|
| + << " and error: " << QuicErrorCodeToString(frame.error_code)
|
| + << " and reason: " << frame.reason_phrase;
|
|
|
| goaway_received_ = true;
|
| visitor_->OnGoAway(frame);
|
| @@ -902,9 +906,9 @@ bool QuicConnection::OnWindowUpdateFrame(const QuicWindowUpdateFrame& frame) {
|
| if (debug_visitor_ != nullptr) {
|
| debug_visitor_->OnWindowUpdateFrame(frame);
|
| }
|
| - DVLOG(1) << ENDPOINT
|
| - << "WINDOW_UPDATE_FRAME received for stream: " << frame.stream_id
|
| - << " with byte offset: " << frame.byte_offset;
|
| + QUIC_DLOG(INFO) << ENDPOINT << "WINDOW_UPDATE_FRAME received for stream: "
|
| + << frame.stream_id
|
| + << " with byte offset: " << frame.byte_offset;
|
| visitor_->OnWindowUpdateFrame(frame);
|
| visitor_->PostProcessAfterData();
|
| should_last_packet_instigate_acks_ = true;
|
| @@ -916,8 +920,8 @@ bool QuicConnection::OnBlockedFrame(const QuicBlockedFrame& frame) {
|
| if (debug_visitor_ != nullptr) {
|
| debug_visitor_->OnBlockedFrame(frame);
|
| }
|
| - DVLOG(1) << ENDPOINT
|
| - << "BLOCKED_FRAME received for stream: " << frame.stream_id;
|
| + QUIC_DLOG(INFO) << ENDPOINT
|
| + << "BLOCKED_FRAME received for stream: " << frame.stream_id;
|
| visitor_->OnBlockedFrame(frame);
|
| visitor_->PostProcessAfterData();
|
| stats_.blocked_frames_received++;
|
| @@ -930,8 +934,8 @@ bool QuicConnection::OnPathCloseFrame(const QuicPathCloseFrame& frame) {
|
| if (debug_visitor_ != nullptr) {
|
| debug_visitor_->OnPathCloseFrame(frame);
|
| }
|
| - DVLOG(1) << ENDPOINT
|
| - << "PATH_CLOSE_FRAME received for path: " << frame.path_id;
|
| + QUIC_DLOG(INFO) << ENDPOINT
|
| + << "PATH_CLOSE_FRAME received for path: " << frame.path_id;
|
| OnPathClosed(frame.path_id);
|
| return connected_;
|
| }
|
| @@ -943,8 +947,8 @@ void QuicConnection::OnPacketComplete() {
|
| return;
|
| }
|
|
|
| - DVLOG(1) << ENDPOINT << "Got packet " << last_header_.packet_number << " for "
|
| - << last_header_.public_header.connection_id;
|
| + QUIC_DVLOG(1) << ENDPOINT << "Got packet " << last_header_.packet_number
|
| + << " for " << last_header_.public_header.connection_id;
|
|
|
| if (FLAGS_quic_reloadable_flag_quic_receive_packet_once_decrypted) {
|
| // An ack will be sent if a missing retransmittable packet was received;
|
| @@ -1087,8 +1091,9 @@ void QuicConnection::SendVersionNegotiationPacket() {
|
| visitor_->OnWriteBlocked();
|
| return;
|
| }
|
| - DVLOG(1) << ENDPOINT << "Sending version negotiation packet: {"
|
| - << QuicVersionVectorToString(framer_.supported_versions()) << "}";
|
| + QUIC_DLOG(INFO) << ENDPOINT << "Sending version negotiation packet: {"
|
| + << QuicVersionVectorToString(framer_.supported_versions())
|
| + << "}";
|
| std::unique_ptr<QuicEncryptedPacket> version_packet(
|
| packet_generator_.SerializeVersionNegotiationPacket(
|
| framer_.supported_versions()));
|
| @@ -1256,8 +1261,8 @@ void QuicConnection::ProcessUdpPacket(const QuicSocketAddress& self_address,
|
| << clock_->ApproximateNow().ToDebuggingValue();
|
| }
|
| time_of_last_received_packet_ = packet.receipt_time();
|
| - DVLOG(1) << ENDPOINT << "time of last received packet: "
|
| - << time_of_last_received_packet_.ToDebuggingValue();
|
| + QUIC_DVLOG(1) << ENDPOINT << "time of last received packet: "
|
| + << time_of_last_received_packet_.ToDebuggingValue();
|
|
|
| ScopedRetransmissionScheduler alarm_delayer(this);
|
| if (!framer_.ProcessPacket(packet)) {
|
| @@ -1271,8 +1276,9 @@ void QuicConnection::ProcessUdpPacket(const QuicSocketAddress& self_address,
|
| debug_visitor_->OnUndecryptablePacket();
|
| }
|
| }
|
| - DVLOG(1) << ENDPOINT << "Unable to process packet. Last packet processed: "
|
| - << last_header_.packet_number;
|
| + QUIC_DVLOG(1) << ENDPOINT
|
| + << "Unable to process packet. Last packet processed: "
|
| + << last_header_.packet_number;
|
| current_packet_data_ = nullptr;
|
| return;
|
| }
|
| @@ -1350,8 +1356,8 @@ bool QuicConnection::ProcessValidatedPacket(const QuicPacketHeader& header) {
|
| }
|
|
|
| if (!Near(header.packet_number, last_header_.packet_number)) {
|
| - DVLOG(1) << ENDPOINT << "Packet " << header.packet_number
|
| - << " out of bounds. Discarding";
|
| + QUIC_DLOG(INFO) << ENDPOINT << "Packet " << header.packet_number
|
| + << " out of bounds. Discarding";
|
| CloseConnection(QUIC_INVALID_PACKET_HEADER, "packet number out of bounds.",
|
| ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
|
| return false;
|
| @@ -1376,7 +1382,7 @@ bool QuicConnection::ProcessValidatedPacket(const QuicPacketHeader& header) {
|
| string error_details =
|
| QuicStrCat(ENDPOINT, "Packet ", header.packet_number,
|
| " without version flag before version negotiated.");
|
| - DLOG(WARNING) << error_details;
|
| + QUIC_DLOG(WARNING) << error_details;
|
| CloseConnection(QUIC_INVALID_VERSION, error_details,
|
| ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
|
| return false;
|
| @@ -1513,8 +1519,8 @@ bool QuicConnection::CanWrite(HasRetransmittableData retransmittable) {
|
| // If the scheduler requires a delay, then we can not send this packet now.
|
| if (!delay.IsZero()) {
|
| send_alarm_->Update(now + delay, QuicTime::Delta::FromMilliseconds(1));
|
| - DVLOG(1) << ENDPOINT << "Delaying sending " << delay.ToMilliseconds()
|
| - << "ms";
|
| + QUIC_DVLOG(1) << ENDPOINT << "Delaying sending " << delay.ToMilliseconds()
|
| + << "ms";
|
| return false;
|
| }
|
| return true;
|
| @@ -1568,16 +1574,16 @@ bool QuicConnection::WritePacket(SerializedPacket* packet) {
|
|
|
| DCHECK_LE(encrypted_length, kMaxPacketSize);
|
| DCHECK_LE(encrypted_length, packet_generator_.GetCurrentMaxPacketLength());
|
| - DVLOG(1) << ENDPOINT << "Sending packet " << packet_number << " : "
|
| - << (IsRetransmittable(*packet) == HAS_RETRANSMITTABLE_DATA
|
| - ? "data bearing "
|
| - : " ack only ")
|
| - << ", encryption level: "
|
| - << QuicUtils::EncryptionLevelToString(packet->encryption_level)
|
| - << ", encrypted length:" << encrypted_length;
|
| - DVLOG(2) << ENDPOINT << "packet(" << packet_number << "): " << std::endl
|
| - << QuicTextUtils::HexDump(
|
| - StringPiece(packet->encrypted_buffer, encrypted_length));
|
| + QUIC_DVLOG(1) << ENDPOINT << "Sending packet " << packet_number << " : "
|
| + << (IsRetransmittable(*packet) == HAS_RETRANSMITTABLE_DATA
|
| + ? "data bearing "
|
| + : " ack only ")
|
| + << ", encryption level: "
|
| + << QuicUtils::EncryptionLevelToString(packet->encryption_level)
|
| + << ", encrypted length:" << encrypted_length;
|
| + QUIC_DVLOG(2) << ENDPOINT << "packet(" << packet_number << "): " << std::endl
|
| + << QuicTextUtils::HexDump(
|
| + StringPiece(packet->encrypted_buffer, encrypted_length));
|
|
|
| // Measure the RTT from before the write begins to avoid underestimating the
|
| // min_rtt_, especially in cases where the thread blocks or gets swapped out
|
| @@ -1615,10 +1621,11 @@ bool QuicConnection::WritePacket(SerializedPacket* packet) {
|
|
|
| if (result.status == WRITE_STATUS_ERROR) {
|
| OnWriteError(result.error_code);
|
| - DLOG(ERROR) << ENDPOINT << "failed writing " << encrypted_length
|
| - << " from host " << self_address().host().ToString()
|
| - << " to address " << peer_address().ToString()
|
| - << " with error code " << result.error_code;
|
| + QUIC_LOG_FIRST_N(ERROR, 10)
|
| + << ENDPOINT << "failed writing " << encrypted_length
|
| + << " bytes from host " << self_address().host().ToString()
|
| + << " to address " << peer_address().ToString() << " with error code "
|
| + << result.error_code;
|
| return false;
|
| }
|
|
|
| @@ -1641,8 +1648,8 @@ bool QuicConnection::WritePacket(SerializedPacket* packet) {
|
| }
|
| SetPingAlarm();
|
| MaybeSetMtuAlarm();
|
| - DVLOG(1) << ENDPOINT << "time we began writing last sent packet: "
|
| - << packet_send_time.ToDebuggingValue();
|
| + QUIC_DVLOG(1) << ENDPOINT << "time we began writing last sent packet: "
|
| + << packet_send_time.ToDebuggingValue();
|
|
|
| bool reset_retransmission_alarm = sent_packet_manager_->OnPacketSent(
|
| packet, packet->original_path_id, packet->original_packet_number,
|
| @@ -1670,7 +1677,8 @@ bool QuicConnection::WritePacket(SerializedPacket* packet) {
|
|
|
| bool QuicConnection::ShouldDiscardPacket(const SerializedPacket& packet) {
|
| if (!connected_) {
|
| - DVLOG(1) << ENDPOINT << "Not sending packet as connection is disconnected.";
|
| + QUIC_DLOG(INFO) << ENDPOINT
|
| + << "Not sending packet as connection is disconnected.";
|
| return true;
|
| }
|
|
|
| @@ -1679,8 +1687,9 @@ bool QuicConnection::ShouldDiscardPacket(const SerializedPacket& packet) {
|
| packet.encryption_level == ENCRYPTION_NONE) {
|
| // Drop packets that are NULL encrypted since the peer won't accept them
|
| // anymore.
|
| - DVLOG(1) << ENDPOINT << "Dropping NULL encrypted packet: " << packet_number
|
| - << " since the connection is forward secure.";
|
| + QUIC_DLOG(INFO) << ENDPOINT
|
| + << "Dropping NULL encrypted packet: " << packet_number
|
| + << " since the connection is forward secure.";
|
| return true;
|
| }
|
|
|
| @@ -1696,7 +1705,7 @@ void QuicConnection::OnWriteError(int error_code) {
|
|
|
| const string error_details = QuicStrCat(
|
| "Write failed with error: ", error_code, " (", strerror(error_code), ")");
|
| - DVLOG(1) << ENDPOINT << error_details;
|
| + QUIC_LOG_FIRST_N(ERROR, 2) << ENDPOINT << error_details;
|
| // We can't send an error as the socket is presumably borked.
|
| switch (error_code) {
|
| case kMessageTooBigErrorCode:
|
| @@ -1888,7 +1897,7 @@ const QuicDecrypter* QuicConnection::alternative_decrypter() const {
|
|
|
| void QuicConnection::QueueUndecryptablePacket(
|
| const QuicEncryptedPacket& packet) {
|
| - DVLOG(1) << ENDPOINT << "Queueing undecryptable packet.";
|
| + QUIC_DVLOG(1) << ENDPOINT << "Queueing undecryptable packet.";
|
| undecryptable_packets_.push_back(packet.Clone());
|
| }
|
|
|
| @@ -1898,14 +1907,14 @@ void QuicConnection::MaybeProcessUndecryptablePackets() {
|
| }
|
|
|
| while (connected_ && !undecryptable_packets_.empty()) {
|
| - DVLOG(1) << ENDPOINT << "Attempting to process undecryptable packet";
|
| + QUIC_DVLOG(1) << ENDPOINT << "Attempting to process undecryptable packet";
|
| QuicEncryptedPacket* packet = undecryptable_packets_.front().get();
|
| if (!framer_.ProcessPacket(*packet) &&
|
| framer_.error() == QUIC_DECRYPTION_FAILURE) {
|
| - DVLOG(1) << ENDPOINT << "Unable to process undecryptable packet...";
|
| + QUIC_DVLOG(1) << ENDPOINT << "Unable to process undecryptable packet...";
|
| break;
|
| }
|
| - DVLOG(1) << ENDPOINT << "Processed undecryptable packet!";
|
| + QUIC_DVLOG(1) << ENDPOINT << "Processed undecryptable packet!";
|
| ++stats_.packets_processed;
|
| undecryptable_packets_.pop_front();
|
| }
|
| @@ -1932,13 +1941,13 @@ void QuicConnection::CloseConnection(
|
| ConnectionCloseBehavior connection_close_behavior) {
|
| DCHECK(!error_details.empty());
|
| if (!connected_) {
|
| - DVLOG(1) << "Connection is already closed.";
|
| + QUIC_DLOG(INFO) << "Connection is already closed.";
|
| return;
|
| }
|
|
|
| - DVLOG(1) << ENDPOINT << "Closing connection: " << connection_id()
|
| - << ", with error: " << QuicErrorCodeToString(error) << " (" << error
|
| - << "), and details: " << error_details;
|
| + QUIC_DLOG(INFO) << ENDPOINT << "Closing connection: " << connection_id()
|
| + << ", with error: " << QuicErrorCodeToString(error) << " ("
|
| + << error << "), and details: " << error_details;
|
|
|
| if (connection_close_behavior ==
|
| ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET) {
|
| @@ -1961,7 +1970,7 @@ void QuicConnection::CloseConnection(
|
| void QuicConnection::SendConnectionClosePacket(QuicErrorCode error,
|
| const string& details,
|
| AckBundling ack_mode) {
|
| - DVLOG(1) << ENDPOINT << "Sending connection close packet.";
|
| + QUIC_DLOG(INFO) << ENDPOINT << "Sending connection close packet.";
|
| ClearQueuedPackets();
|
| ScopedPacketBundler ack_bundler(this, ack_mode);
|
| QuicConnectionCloseFrame* frame = new QuicConnectionCloseFrame();
|
| @@ -1976,7 +1985,7 @@ void QuicConnection::TearDownLocalConnectionState(
|
| const string& error_details,
|
| ConnectionCloseSource source) {
|
| if (!connected_) {
|
| - DVLOG(1) << "Connection is already closed.";
|
| + QUIC_DLOG(INFO) << "Connection is already closed.";
|
| return;
|
| }
|
| connected_ = false;
|
| @@ -1998,7 +2007,7 @@ void QuicConnection::TearDownLocalConnectionState(
|
| }
|
|
|
| void QuicConnection::CancelAllAlarms() {
|
| - DVLOG(1) << "Cancelling all QuicConnection alarms.";
|
| + QUIC_DVLOG(1) << "Cancelling all QuicConnection alarms.";
|
|
|
| ack_alarm_->Cancel();
|
| ping_alarm_->Cancel();
|
| @@ -2017,8 +2026,8 @@ void QuicConnection::SendGoAway(QuicErrorCode error,
|
| }
|
| goaway_sent_ = true;
|
|
|
| - DVLOG(1) << ENDPOINT << "Going away with error "
|
| - << QuicErrorCodeToString(error) << " (" << error << ")";
|
| + QUIC_DLOG(INFO) << ENDPOINT << "Going away with error "
|
| + << QuicErrorCodeToString(error) << " (" << error << ")";
|
|
|
| // Opportunistically bundle an ack with this outgoing packet.
|
| ScopedPacketBundler ack_bundler(this, SEND_ACK_IF_PENDING);
|
| @@ -2087,15 +2096,15 @@ void QuicConnection::CheckForTimeout() {
|
| // is accurate time. However, this should not change the behavior of
|
| // timeout handling.
|
| QuicTime::Delta idle_duration = now - time_of_last_packet;
|
| - DVLOG(1) << ENDPOINT << "last packet "
|
| - << time_of_last_packet.ToDebuggingValue()
|
| - << " now:" << now.ToDebuggingValue()
|
| - << " idle_duration:" << idle_duration.ToMicroseconds()
|
| - << " idle_network_timeout: "
|
| - << idle_network_timeout_.ToMicroseconds();
|
| + QUIC_DVLOG(1) << ENDPOINT << "last packet "
|
| + << time_of_last_packet.ToDebuggingValue()
|
| + << " now:" << now.ToDebuggingValue()
|
| + << " idle_duration:" << idle_duration.ToMicroseconds()
|
| + << " idle_network_timeout: "
|
| + << idle_network_timeout_.ToMicroseconds();
|
| if (idle_duration >= idle_network_timeout_) {
|
| const string error_details = "No recent network activity.";
|
| - DVLOG(1) << ENDPOINT << error_details;
|
| + QUIC_DVLOG(1) << ENDPOINT << error_details;
|
| CloseConnection(QUIC_NETWORK_IDLE_TIMEOUT, error_details,
|
| idle_timeout_connection_close_behavior_);
|
| return;
|
| @@ -2103,12 +2112,13 @@ void QuicConnection::CheckForTimeout() {
|
|
|
| if (!handshake_timeout_.IsInfinite()) {
|
| QuicTime::Delta connected_duration = now - stats_.connection_creation_time;
|
| - DVLOG(1) << ENDPOINT
|
| - << "connection time: " << connected_duration.ToMicroseconds()
|
| - << " handshake timeout: " << handshake_timeout_.ToMicroseconds();
|
| + QUIC_DVLOG(1) << ENDPOINT
|
| + << "connection time: " << connected_duration.ToMicroseconds()
|
| + << " handshake timeout: "
|
| + << handshake_timeout_.ToMicroseconds();
|
| if (connected_duration >= handshake_timeout_) {
|
| const string error_details = "Handshake timeout expired.";
|
| - DVLOG(1) << ENDPOINT << error_details;
|
| + QUIC_DVLOG(1) << ENDPOINT << error_details;
|
| CloseConnection(QUIC_HANDSHAKE_TIMEOUT, error_details,
|
| ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
|
| return;
|
| @@ -2192,11 +2202,11 @@ QuicConnection::ScopedPacketBundler::ScopedPacketBundler(
|
| // Move generator into batch mode. If caller wants us to include an ack,
|
| // check the delayed-ack timer to see if there's ack info to be sent.
|
| if (!already_in_batch_mode_) {
|
| - DVLOG(2) << "Entering Batch Mode.";
|
| + QUIC_DVLOG(2) << "Entering Batch Mode.";
|
| connection_->packet_generator_.StartBatchOperations();
|
| }
|
| if (ShouldSendAck(ack_mode)) {
|
| - DVLOG(1) << "Bundling ack with outgoing packet.";
|
| + QUIC_DVLOG(1) << "Bundling ack with outgoing packet.";
|
| DCHECK(ack_mode == SEND_ACK || connection_->ack_frame_updated() ||
|
| connection_->stop_waiting_count_ > 1);
|
| connection_->SendAck();
|
| @@ -2227,7 +2237,7 @@ QuicConnection::ScopedPacketBundler::~ScopedPacketBundler() {
|
| }
|
| // If we changed the generator's batch state, restore original batch state.
|
| if (!already_in_batch_mode_) {
|
| - DVLOG(2) << "Leaving Batch Mode.";
|
| + QUIC_DVLOG(2) << "Leaving Batch Mode.";
|
| connection_->packet_generator_.FinishBatchOperations();
|
|
|
| // Once all transmissions are done, check if there is any outstanding data
|
| @@ -2350,7 +2360,7 @@ void QuicConnection::DiscoverMtu() {
|
| packet_number_of_last_sent_packet_ + packets_between_mtu_probes_ + 1;
|
| ++mtu_probe_count_;
|
|
|
| - DVLOG(2) << "Sending a path MTU discovery packet #" << mtu_probe_count_;
|
| + QUIC_DVLOG(2) << "Sending a path MTU discovery packet #" << mtu_probe_count_;
|
| SendMtuDiscoveryPacket(mtu_discovery_target_);
|
|
|
| DCHECK(!mtu_discovery_alarm_->IsSet());
|
| @@ -2380,10 +2390,10 @@ void QuicConnection::StartPeerMigration(
|
| QUIC_BUG << "Migration underway or no new migration started.";
|
| return;
|
| }
|
| - DVLOG(1) << ENDPOINT << "Peer's ip:port changed from "
|
| - << peer_address_.ToString() << " to "
|
| - << last_packet_source_address_.ToString()
|
| - << ", migrating connection.";
|
| + QUIC_DLOG(INFO) << ENDPOINT << "Peer's ip:port changed from "
|
| + << peer_address_.ToString() << " to "
|
| + << last_packet_source_address_.ToString()
|
| + << ", migrating connection.";
|
|
|
| highest_packet_sent_before_peer_migration_ =
|
| packet_number_of_last_sent_packet_;
|
|
|