Improve logging by adding more ToString methods and refactor gfe-relnote: change debug-only logs, not flag-protected PiperOrigin-RevId: 272905128 Change-Id: I501df69f6440adfe13dd92a4a7debd97d2534bd0
diff --git a/quic/core/frames/quic_frame.cc b/quic/core/frames/quic_frame.cc index b23f9c0..5e85fc0 100644 --- a/quic/core/frames/quic_frame.cc +++ b/quic/core/frames/quic_frame.cc
@@ -298,7 +298,7 @@ break; } case CRYPTO_FRAME: { - os << "type { CRYPTO_FRAME } " << frame.crypto_frame; + os << "type { CRYPTO_FRAME } " << *(frame.crypto_frame); break; } case MTU_DISCOVERY_FRAME: {
diff --git a/quic/core/quic_connection.cc b/quic/core/quic_connection.cc index ce1e6c4..9cabfc5 100644 --- a/quic/core/quic_connection.cc +++ b/quic/core/quic_connection.cc
@@ -1368,8 +1368,12 @@ ++stats_.num_connectivity_probing_received; } - QUIC_DVLOG(1) << ENDPOINT << "Got packet " << last_header_.packet_number - << " for " + QUIC_DVLOG(1) << ENDPOINT << "Got" + << (SupportsMultiplePacketNumberSpaces() + ? (" " + EncryptionLevelToString( + last_decrypted_packet_level_)) + : "") + << " packet " << last_header_.packet_number << " for " << GetServerConnectionIdAsRecipient(last_header_, perspective_); QUIC_DLOG_IF(INFO, current_packet_content_ == SECOND_FRAME_IS_PADDING) @@ -1447,8 +1451,7 @@ clock_->ApproximateNow(), sent_packet_manager_.GetRttStats()); } else { QUIC_DLOG(INFO) << ENDPOINT << "Not updating ACK timeout for " - << QuicUtils::EncryptionLevelToString( - last_decrypted_packet_level_) + << EncryptionLevelToString(last_decrypted_packet_level_) << " as we do not have the corresponding encrypter"; } @@ -1483,12 +1486,12 @@ sent_packet_manager_.GetLeastUnacked() + max_tracked_packets_) { CloseConnection( QUIC_TOO_MANY_OUTSTANDING_SENT_PACKETS, - QuicStrCat( - "More than ", max_tracked_packets_, " outstanding, least_unacked: ", - sent_packet_manager_.GetLeastUnacked().ToUint64(), - ", packets_processed: ", stats_.packets_processed, - ", last_decrypted_packet_level: ", - QuicUtils::EncryptionLevelToString(last_decrypted_packet_level_)), + QuicStrCat("More than ", max_tracked_packets_, + " outstanding, least_unacked: ", + sent_packet_manager_.GetLeastUnacked().ToUint64(), + ", packets_processed: ", stats_.packets_processed, + ", last_decrypted_packet_level: ", + EncryptionLevelToString(last_decrypted_packet_level_)), ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET); } } @@ -1621,7 +1624,7 @@ // handshake deadlock. QUIC_DVLOG(1) << ENDPOINT << "Failed to send control frame: " << frame << " at encryption level: " - << QuicUtils::EncryptionLevelToString(encryption_level_); + << EncryptionLevelToString(encryption_level_); return false; } ScopedPacketFlusher flusher(this); @@ -1713,9 +1716,9 @@ QUIC_DVLOG(1) << ENDPOINT << "Received undecryptable packet of length " << packet.length() << " with" << (has_decryption_key ? "" : "out") << " key at level " - << QuicUtils::EncryptionLevelToString(decryption_level) + << EncryptionLevelToString(decryption_level) << " while connection is at encryption level " - << QuicUtils::EncryptionLevelToString(encryption_level_); + << EncryptionLevelToString(encryption_level_); DCHECK(GetQuicRestartFlag(quic_framer_uses_undecryptable_upcall)); QUIC_RESTART_FLAG_COUNT_N(quic_framer_uses_undecryptable_upcall, 1, 7); DCHECK(EncryptionLevelIsValid(decryption_level)); @@ -2166,7 +2169,7 @@ QuicFrame updated_ack_frame = GetUpdatedAckFrame(); QUIC_BUG_IF(updated_ack_frame.ack_frame->packets.Empty()) << ENDPOINT << "Attempted to opportunistically bundle an empty " - << QuicUtils::EncryptionLevelToString(encryption_level_) << " ACK, " + << EncryptionLevelToString(encryption_level_) << " ACK, " << (has_pending_ack ? "" : "!") << "has_pending_ack, stop_waiting_count_ " << stop_waiting_count_; frames.push_back(updated_ack_frame); @@ -2276,7 +2279,7 @@ ? "data bearing " : " ack only ") << ", encryption level: " - << QuicUtils::EncryptionLevelToString(packet->encryption_level) + << EncryptionLevelToString(packet->encryption_level) << ", encrypted length:" << encrypted_length; QUIC_DVLOG(2) << ENDPOINT << "packet(" << packet_number << "): " << std::endl << QuicTextUtils::HexDump(QuicStringPiece( @@ -2753,8 +2756,8 @@ void QuicConnection::SetDefaultEncryptionLevel(EncryptionLevel level) { QUIC_DVLOG(1) << ENDPOINT << "Setting default encryption level from " - << QuicUtils::EncryptionLevelToString(encryption_level_) - << " to " << QuicUtils::EncryptionLevelToString(level); + << EncryptionLevelToString(encryption_level_) << " to " + << EncryptionLevelToString(level); if (level != encryption_level_ && packet_generator_.HasPendingFrames()) { // Flush all queued frames when encryption level changes. ScopedPacketFlusher flusher(this); @@ -3810,7 +3813,7 @@ // A forward secure packet has been received. QUIC_BUG_IF(encryption_level_ != ENCRYPTION_FORWARD_SECURE) << ENDPOINT << "Unexpected connection close encryption level " - << QuicUtils::EncryptionLevelToString(encryption_level_); + << EncryptionLevelToString(encryption_level_); return ENCRYPTION_FORWARD_SECURE; } if (framer_.HasEncrypterOfEncryptionLevel(ENCRYPTION_ZERO_RTT)) { @@ -3842,12 +3845,13 @@ if (!framer_.HasEncrypterOfEncryptionLevel( QuicUtils::GetEncryptionLevel(static_cast<PacketNumberSpace>(i)))) { QUIC_BUG << ENDPOINT << "Cannot send ACKs for packet number space " - << static_cast<uint32_t>(i) + << PacketNumberSpaceToString(static_cast<PacketNumberSpace>(i)) << " without corresponding encrypter"; continue; } - QUIC_DVLOG(1) << ENDPOINT << "Sending ACK of packet number space: " - << static_cast<uint32_t>(i); + QUIC_DVLOG(1) << ENDPOINT << "Sending ACK of packet number space " + << PacketNumberSpaceToString( + static_cast<PacketNumberSpace>(i)); // Switch to the appropriate encryption level. SetDefaultEncryptionLevel( QuicUtils::GetEncryptionLevel(static_cast<PacketNumberSpace>(i)));
diff --git a/quic/core/quic_framer.cc b/quic/core/quic_framer.cc index e10270d..6b55cfc 100644 --- a/quic/core/quic_framer.cc +++ b/quic/core/quic_framer.cc
@@ -4127,8 +4127,8 @@ DCHECK_GE(level, decrypter_level_); DCHECK(!version_.KnowsWhichDecrypterToUse()); QUIC_DVLOG(1) << ENDPOINT << "Setting decrypter from level " - << QuicUtils::EncryptionLevelToString(decrypter_level_) - << " to " << QuicUtils::EncryptionLevelToString(level); + << EncryptionLevelToString(decrypter_level_) << " to " + << EncryptionLevelToString(level); decrypter_[decrypter_level_] = nullptr; decrypter_[level] = std::move(decrypter); decrypter_level_ = level; @@ -4141,9 +4141,8 @@ DCHECK_NE(level, decrypter_level_); DCHECK(!version_.KnowsWhichDecrypterToUse()); QUIC_DVLOG(1) << ENDPOINT << "Setting alternative decrypter from level " - << QuicUtils::EncryptionLevelToString( - alternative_decrypter_level_) - << " to " << QuicUtils::EncryptionLevelToString(level); + << EncryptionLevelToString(alternative_decrypter_level_) + << " to " << EncryptionLevelToString(level); if (alternative_decrypter_level_ != NUM_ENCRYPTION_LEVELS) { decrypter_[alternative_decrypter_level_] = nullptr; } @@ -4156,14 +4155,14 @@ std::unique_ptr<QuicDecrypter> decrypter) { DCHECK(version_.KnowsWhichDecrypterToUse()); QUIC_DVLOG(1) << ENDPOINT << "Installing decrypter at level " - << QuicUtils::EncryptionLevelToString(level); + << EncryptionLevelToString(level); decrypter_[level] = std::move(decrypter); } void QuicFramer::RemoveDecrypter(EncryptionLevel level) { DCHECK(version_.KnowsWhichDecrypterToUse()); QUIC_DVLOG(1) << ENDPOINT << "Removing decrypter at level " - << QuicUtils::EncryptionLevelToString(level); + << EncryptionLevelToString(level); decrypter_[level] = nullptr; } @@ -4188,7 +4187,7 @@ DCHECK_GE(level, 0); DCHECK_LT(level, NUM_ENCRYPTION_LEVELS); QUIC_DVLOG(1) << ENDPOINT << "Setting encrypter at level " - << QuicUtils::EncryptionLevelToString(level); + << EncryptionLevelToString(level); encrypter_[level] = std::move(encrypter); } @@ -4210,7 +4209,7 @@ if (encrypter_[level] == nullptr) { QUIC_BUG << ENDPOINT << "Attempted to encrypt in place without encrypter at level " - << QuicUtils::EncryptionLevelToString(level); + << EncryptionLevelToString(level); RaiseError(QUIC_ENCRYPTION_FAILURE); return 0; } @@ -4334,7 +4333,7 @@ QUIC_DVLOG(1) << ENDPOINT << "No decrypter available for removing header protection at level " - << QuicUtils::EncryptionLevelToString(expected_decryption_level); + << EncryptionLevelToString(expected_decryption_level); return false; } @@ -4455,7 +4454,7 @@ DCHECK(packet_number.IsInitialized()); if (encrypter_[level] == nullptr) { QUIC_BUG << ENDPOINT << "Attempted to encrypt without encrypter at level " - << QuicUtils::EncryptionLevelToString(level); + << EncryptionLevelToString(level); RaiseError(QUIC_ENCRYPTION_FAILURE); return 0; }
diff --git a/quic/core/quic_packet_creator.cc b/quic/core/quic_packet_creator.cc index b717054..e7f5185 100644 --- a/quic/core/quic_packet_creator.cc +++ b/quic/core/quic_packet_creator.cc
@@ -41,10 +41,10 @@ case ENCRYPTION_FORWARD_SECURE: QUIC_BUG << "Try to derive long header type for packet with encryption level: " - << QuicUtils::EncryptionLevelToString(level); + << EncryptionLevelToString(level); return INVALID_PACKET_TYPE; default: - QUIC_BUG << QuicUtils::EncryptionLevelToString(level); + QUIC_BUG << EncryptionLevelToString(level); return INVALID_PACKET_TYPE; } } @@ -1267,15 +1267,15 @@ bool save_retransmittable_frames, TransmissionType transmission_type) { QUIC_DVLOG(1) << ENDPOINT << "Adding frame with transmission type " - << transmission_type << ": " << frame; + << TransmissionTypeToString(transmission_type) << ": " << frame; if (frame.type == STREAM_FRAME && !QuicUtils::IsCryptoStreamId(framer_->transport_version(), frame.stream_frame.stream_id) && (packet_.encryption_level == ENCRYPTION_INITIAL || packet_.encryption_level == ENCRYPTION_HANDSHAKE)) { - const std::string error_details = QuicStrCat( - "Cannot send stream data with level: ", - QuicUtils::EncryptionLevelToString(packet_.encryption_level)); + const std::string error_details = + QuicStrCat("Cannot send stream data with level: ", + EncryptionLevelToString(packet_.encryption_level)); QUIC_BUG << error_details; delegate_->OnUnrecoverableError( QUIC_ATTEMPT_TO_SEND_UNENCRYPTED_STREAM_DATA, error_details); @@ -1370,8 +1370,9 @@ bool success = AddFrame(QuicFrame(QuicPaddingFrame(padding_bytes)), false, packet_.transmission_type); - QUIC_BUG_IF(!success) << "Failed to add padding_bytes:" << padding_bytes - << " transmission_type:" << packet_.transmission_type; + QUIC_BUG_IF(!success) << "Failed to add padding_bytes: " << padding_bytes + << " transmission_type: " + << TransmissionTypeToString(packet_.transmission_type); } bool QuicPacketCreator::IncludeNonceInPublicHeader() const { @@ -1429,7 +1430,7 @@ if (!can_set_transmission_type()) { QUIC_DVLOG_IF(1, type != packet_.transmission_type) << ENDPOINT << "Setting Transmission type to " - << QuicUtils::TransmissionTypeToString(type); + << TransmissionTypeToString(type); packet_.transmission_type = type; }
diff --git a/quic/core/quic_sent_packet_manager.cc b/quic/core/quic_sent_packet_manager.cc index 6baac98..a32a253 100644 --- a/quic/core/quic_sent_packet_manager.cc +++ b/quic/core/quic_sent_packet_manager.cc
@@ -521,8 +521,7 @@ (!session_decides_what_to_write() || transmission_type != RTO_RETRANSMISSION)) && !unacked_packets_.HasRetransmittableFrames(*transmission_info)) - << "transmission_type: " - << QuicUtils::TransmissionTypeToString(transmission_type); + << "transmission_type: " << TransmissionTypeToString(transmission_type); // Handshake packets should never be sent as probing retransmissions. DCHECK(pto_enabled_ || !transmission_info->has_crypto_handshake || transmission_type != PROBING_RETRANSMISSION); @@ -690,8 +689,7 @@ // retransmission and no new data gets acked. QUIC_DVLOG(1) << "Detect spurious retransmitted packet " << packet_number << " transmission type: " - << QuicUtils::TransmissionTypeToString( - info->transmission_type); + << TransmissionTypeToString(info->transmission_type); RecordSpuriousRetransmissions(*info, packet_number); } } @@ -1372,7 +1370,7 @@ << ", packets_acked_: " << packets_acked_; } else { QUIC_PEER_BUG << "Received " - << QuicUtils::EncryptionLevelToString(ack_decrypted_level) + << EncryptionLevelToString(ack_decrypted_level) << " ack for unackable packet: " << acked_packet.packet_number << " with state: " << QuicUtils::SentPacketStateToString(info->state); @@ -1386,7 +1384,7 @@ continue; } QUIC_DVLOG(1) << ENDPOINT << "Got an " - << QuicUtils::EncryptionLevelToString(ack_decrypted_level) + << EncryptionLevelToString(ack_decrypted_level) << " ack for packet " << acked_packet.packet_number << " , state: " << QuicUtils::SentPacketStateToString(info->state);
diff --git a/quic/core/quic_types.cc b/quic/core/quic_types.cc index 46f809d..a8373c1 100644 --- a/quic/core/quic_types.cc +++ b/quic/core/quic_types.cc
@@ -457,13 +457,56 @@ return os; } +std::string TransmissionTypeToString(TransmissionType transmission_type) { + switch (transmission_type) { + RETURN_STRING_LITERAL(NOT_RETRANSMISSION); + RETURN_STRING_LITERAL(HANDSHAKE_RETRANSMISSION); + RETURN_STRING_LITERAL(ALL_UNACKED_RETRANSMISSION); + RETURN_STRING_LITERAL(ALL_INITIAL_RETRANSMISSION); + RETURN_STRING_LITERAL(LOSS_RETRANSMISSION); + RETURN_STRING_LITERAL(RTO_RETRANSMISSION); + RETURN_STRING_LITERAL(TLP_RETRANSMISSION); + RETURN_STRING_LITERAL(PROBING_RETRANSMISSION); + default: + // Some varz rely on this behavior for statistic collection. + if (transmission_type == LAST_TRANSMISSION_TYPE + 1) { + return "INVALID_TRANSMISSION_TYPE"; + } + return QuicStrCat("Unknown(", static_cast<int>(transmission_type), ")"); + break; + } +} + +std::string PacketNumberSpaceToString(PacketNumberSpace packet_number_space) { + switch (packet_number_space) { + RETURN_STRING_LITERAL(INITIAL_DATA); + RETURN_STRING_LITERAL(HANDSHAKE_DATA); + RETURN_STRING_LITERAL(APPLICATION_DATA); + default: + return QuicStrCat("Unknown(", static_cast<int>(packet_number_space), ")"); + break; + } +} + +std::string EncryptionLevelToString(EncryptionLevel level) { + switch (level) { + RETURN_STRING_LITERAL(ENCRYPTION_INITIAL); + RETURN_STRING_LITERAL(ENCRYPTION_HANDSHAKE); + RETURN_STRING_LITERAL(ENCRYPTION_ZERO_RTT); + RETURN_STRING_LITERAL(ENCRYPTION_FORWARD_SECURE); + default: + return QuicStrCat("Unknown(", static_cast<int>(level), ")"); + break; + } +} + std::string QuicConnectionCloseTypeString(QuicConnectionCloseType type) { switch (type) { RETURN_STRING_LITERAL(GOOGLE_QUIC_CONNECTION_CLOSE); RETURN_STRING_LITERAL(IETF_QUIC_TRANSPORT_CONNECTION_CLOSE); RETURN_STRING_LITERAL(IETF_QUIC_APPLICATION_CONNECTION_CLOSE); default: - return QuicStrCat("Unknown: ", static_cast<int>(type)); + return QuicStrCat("Unknown(", static_cast<int>(type), ")"); break; } }
diff --git a/quic/core/quic_types.h b/quic/core/quic_types.h index bd7ff55..e1c9c68 100644 --- a/quic/core/quic_types.h +++ b/quic/core/quic_types.h
@@ -157,6 +157,9 @@ LAST_TRANSMISSION_TYPE = PROBING_RETRANSMISSION, }; +QUIC_EXPORT_PRIVATE std::string TransmissionTypeToString( + TransmissionType transmission_type); + enum HasRetransmittableData : uint8_t { NO_RETRANSMITTABLE_DATA, HAS_RETRANSMITTABLE_DATA, @@ -407,6 +410,8 @@ return ENCRYPTION_INITIAL <= level && level < NUM_ENCRYPTION_LEVELS; } +QUIC_EXPORT_PRIVATE std::string EncryptionLevelToString(EncryptionLevel level); + enum AddressChangeType : uint8_t { // IP address and port remain unchanged. NO_CHANGE, @@ -630,6 +635,9 @@ NUM_PACKET_NUMBER_SPACES, }; +QUIC_EXPORT_PRIVATE std::string PacketNumberSpaceToString( + PacketNumberSpace packet_number_space); + enum AckMode { TCP_ACKING, ACK_DECIMATION, ACK_DECIMATION_WITH_REORDERING }; // Used to return the result of processing a received ACK frame.
diff --git a/quic/core/quic_utils.cc b/quic/core/quic_utils.cc index da2cb1a..07565ee 100644 --- a/quic/core/quic_utils.cc +++ b/quic/core/quic_utils.cc
@@ -142,33 +142,6 @@ case x: \ return #x; -// static -const char* QuicUtils::EncryptionLevelToString(EncryptionLevel level) { - switch (level) { - RETURN_STRING_LITERAL(ENCRYPTION_INITIAL); - RETURN_STRING_LITERAL(ENCRYPTION_HANDSHAKE); - RETURN_STRING_LITERAL(ENCRYPTION_ZERO_RTT); - RETURN_STRING_LITERAL(ENCRYPTION_FORWARD_SECURE); - RETURN_STRING_LITERAL(NUM_ENCRYPTION_LEVELS); - } - return "INVALID_ENCRYPTION_LEVEL"; -} - -// static -const char* QuicUtils::TransmissionTypeToString(TransmissionType type) { - switch (type) { - RETURN_STRING_LITERAL(NOT_RETRANSMISSION); - RETURN_STRING_LITERAL(HANDSHAKE_RETRANSMISSION); - RETURN_STRING_LITERAL(LOSS_RETRANSMISSION); - RETURN_STRING_LITERAL(ALL_UNACKED_RETRANSMISSION); - RETURN_STRING_LITERAL(ALL_INITIAL_RETRANSMISSION); - RETURN_STRING_LITERAL(RTO_RETRANSMISSION); - RETURN_STRING_LITERAL(TLP_RETRANSMISSION); - RETURN_STRING_LITERAL(PROBING_RETRANSMISSION); - } - return "INVALID_TRANSMISSION_TYPE"; -} - std::string QuicUtils::AddressChangeTypeToString(AddressChangeType type) { switch (type) { RETURN_STRING_LITERAL(NO_CHANGE); @@ -359,7 +332,7 @@ case PROBING_RETRANSMISSION: return PROBE_RETRANSMITTED; default: - QUIC_BUG << QuicUtils::TransmissionTypeToString(retransmission_type) + QUIC_BUG << TransmissionTypeToString(retransmission_type) << " is not a retransmission_type"; return UNACKABLE; }
diff --git a/quic/core/quic_utils.h b/quic/core/quic_utils.h index de855a0..25ab7bb 100644 --- a/quic/core/quic_utils.h +++ b/quic/core/quic_utils.h
@@ -50,12 +50,6 @@ // to |out|. static void SerializeUint128Short(QuicUint128 v, uint8_t* out); - // Returns the level of encryption as a char* - static const char* EncryptionLevelToString(EncryptionLevel level); - - // Returns TransmissionType as a char* - static const char* TransmissionTypeToString(TransmissionType type); - // Returns AddressChangeType as a string. static std::string AddressChangeTypeToString(AddressChangeType type);